diff --git a/build.gradle b/build.gradle index a77c5918752..e32ad04294f 100644 --- a/build.gradle +++ b/build.gradle @@ -75,8 +75,9 @@ subprojects { } dependencies { - implementation group: 'org.slf4j', name: 'slf4j-api', version: '1.7.25' - implementation group: 'org.slf4j', name: 'jcl-over-slf4j', version: '1.7.25' + implementation group: 'org.slf4j', name: 'slf4j-api', version: '1.7.36' + implementation group: 'org.slf4j', name: 'jcl-over-slf4j', version: '1.7.36' + implementation group: 'org.slf4j', name: 'jul-to-slf4j', version: '1.7.36' implementation group: 'ch.qos.logback', name: 'logback-classic', version: '1.2.13' implementation "com.google.code.findbugs:jsr305:3.0.0" implementation group: 'org.springframework', name: 'spring-context', version: "${springVersion}" diff --git a/common/src/main/java/org/tron/common/log/LogService.java b/common/src/main/java/org/tron/common/log/LogService.java index 801e13f54f7..586f175a5b0 100644 --- a/common/src/main/java/org/tron/common/log/LogService.java +++ b/common/src/main/java/org/tron/common/log/LogService.java @@ -2,6 +2,7 @@ import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.joran.JoranConfigurator; +import ch.qos.logback.core.util.StatusPrinter; import java.io.File; import org.slf4j.LoggerFactory; import org.tron.core.exception.TronError; @@ -9,17 +10,18 @@ public class LogService { public static void load(String path) { + LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); try { File file = new File(path); if (!file.exists() || !file.isFile() || !file.canRead()) { return; } - LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); JoranConfigurator configurator = new JoranConfigurator(); configurator.setContext(lc); lc.reset(); configurator.doConfigure(file); } catch (Exception e) { + StatusPrinter.printInCaseOfErrorsOrWarnings(lc); throw new TronError(e, TronError.ErrCode.LOG_LOAD); } } diff --git a/common/src/main/java/org/tron/common/parameter/CommonParameter.java b/common/src/main/java/org/tron/common/parameter/CommonParameter.java index a602a660f8f..11eab7a373e 100644 --- a/common/src/main/java/org/tron/common/parameter/CommonParameter.java +++ b/common/src/main/java/org/tron/common/parameter/CommonParameter.java @@ -4,10 +4,15 @@ import java.net.InetAddress; import java.net.InetSocketAddress; import java.util.ArrayList; +import java.util.Enumeration; import java.util.List; import java.util.Set; +import java.util.logging.Level; +import java.util.logging.LogManager; +import java.util.logging.Logger; import lombok.Getter; import lombok.Setter; +import org.slf4j.bridge.SLF4JBridgeHandler; import org.tron.common.args.GenesisBlock; import org.tron.common.config.DbBackupConfig; import org.tron.common.cron.CronExpression; @@ -750,6 +755,31 @@ public class CommonParameter { @Setter public long allowTvmBlob; + static { + LogManager.getLogManager().reset(); + SLF4JBridgeHandler.removeHandlersForRootLogger(); + SLF4JBridgeHandler.install(); + Logger.getLogger("").setLevel(Level.ALL); // Root logger. + LogManager logManager = LogManager.getLogManager(); + + setLoggerLevel("io.grpc"); + setLoggerLevel("io.netty"); + + Enumeration names = logManager.getLoggerNames(); + while (names.hasMoreElements()) { + String name = names.nextElement(); + if (name.startsWith("io.grpc") || name.startsWith("io.netty")) { + setLoggerLevel(name); + } + } + } + + private static void setLoggerLevel(String name) { + Logger logger = Logger.getLogger(name); + logger.setLevel(Level.FINEST); + logger.setUseParentHandlers(true); + } + private static double calcMaxTimeRatio() { //return max(2.0, min(5.0, 5 * 4.0 / max(Runtime.getRuntime().availableProcessors(), 1))); return 5.0; diff --git a/common/src/main/java/org/tron/common/setting/RocksDbSettings.java b/common/src/main/java/org/tron/common/setting/RocksDbSettings.java index d5df5e261b5..73508fd0039 100644 --- a/common/src/main/java/org/tron/common/setting/RocksDbSettings.java +++ b/common/src/main/java/org/tron/common/setting/RocksDbSettings.java @@ -8,9 +8,7 @@ import org.rocksdb.BlockBasedTableConfig; import org.rocksdb.BloomFilter; import org.rocksdb.ComparatorOptions; -import org.rocksdb.InfoLogLevel; import org.rocksdb.LRUCache; -import org.rocksdb.Logger; import org.rocksdb.Options; import org.rocksdb.RocksDB; import org.rocksdb.Statistics; @@ -182,13 +180,6 @@ public static Options getOptionsByDbName(String dbName) { RocksDbSettings settings = getSettings(); Options options = new Options(); - - options.setLogger(new Logger(options) { - @Override - protected void log(InfoLogLevel infoLogLevel, String logMsg) { - rocksDbLogger.info("{} {}", dbName, logMsg); - } - }); // most of these options are suggested by https://github.com/facebook/rocksdb/wiki/Set-Up-Options // general options diff --git a/common/src/main/java/org/tron/common/utils/DebugInterceptor.java b/common/src/main/java/org/tron/common/utils/DebugInterceptor.java new file mode 100644 index 00000000000..3346642764a --- /dev/null +++ b/common/src/main/java/org/tron/common/utils/DebugInterceptor.java @@ -0,0 +1,95 @@ +package org.tron.common.utils; + +import io.grpc.CallOptions; +import io.grpc.Channel; +import io.grpc.ClientCall; +import io.grpc.ClientInterceptor; +import io.grpc.ForwardingClientCall; +import io.grpc.ForwardingClientCallListener; +import io.grpc.Metadata; +import io.grpc.MethodDescriptor; +import io.grpc.Status; +import java.util.concurrent.atomic.AtomicLong; +import lombok.extern.slf4j.Slf4j; + +@Slf4j(topic = "grpcClient") +/** + * A gRPC ClientInterceptor that provides deep, event-level logging to debug complex + * concurrency and hanging issues. It meticulously logs the sequence of events across + * the application thread and gRPC's internal I/O threads. + */ +public class DebugInterceptor implements ClientInterceptor { + + private final AtomicLong callIdCounter = new AtomicLong(0); + + @Override + public ClientCall interceptCall( + MethodDescriptor method, CallOptions callOptions, Channel next) { + logger.debug("callId={}, event=interceptCall, method={}, callOptions={}", + callIdCounter.incrementAndGet(), method.getFullMethodName(), callOptions); + ClientCall call = next.newCall(method, callOptions); + return new ForwardingClientCall.SimpleForwardingClientCall(call) { + + @Override + public void start(Listener responseListener, Metadata headers) { + logger.debug("callId={}, event=start, headers={}", callIdCounter.get(), headers); + super.start(new ForwardingClientCallListener.SimpleForwardingClientCallListener( + responseListener) { + @Override + public void onHeaders(Metadata headers) { + logger.debug("callId={}, event=onHeaders, headers={}", callIdCounter.get(), headers); + try { + super.onHeaders(headers); + logger.debug("callId={}, event=onHeaders completed", callIdCounter.get()); + } catch (Exception e) { + logger.error("callId={}, event=onHeaders, exception={}", callIdCounter.get(), + e.getMessage(), e); + throw e; + } + } + + @Override + public void onClose(Status status, Metadata trailers) { + logger.debug("callId={}, event=onClose, status={}, trailers={}", + callIdCounter.get(), status, trailers); + try { + super.onClose(status, trailers); + logger.debug("callId={}, event=onClose completed", callIdCounter.get()); + } catch (Exception e) { + logger.error("callId={}, event=onClose, exception={}", callIdCounter.get(), + e.getMessage(), e); + throw e; + } + } + + @Override + public void onMessage(RespT message) { + logger.debug("callId={}, event=onMessage, message={}", callIdCounter.get(), message); + try { + super.onMessage(message); + logger.debug("callId={}, event=onMessage completed", callIdCounter.get()); + } catch (Exception e) { + logger.error("callId={}, event=onMessage, exception={}", callIdCounter.get(), + e.getMessage(), e); + throw e; + } + } + + public void onReady() { + logger.debug("callId={}, event=onReady", callIdCounter.get()); + try { + super.onReady(); + logger.debug("callId={}, event=onReady completed", callIdCounter.get()); + } catch (Exception e) { + logger.error("callId={}, event=onReady, exception={}", callIdCounter.get(), + e.getMessage(), e); + throw e; + } + } + + }, headers); + logger.debug("callId={}, event=start completed", callIdCounter.get()); + } + }; + } +} \ No newline at end of file diff --git a/common/src/main/java/org/tron/common/utils/TimeoutInterceptor.java b/common/src/main/java/org/tron/common/utils/TimeoutInterceptor.java index 07b00e861e8..8ad9b880190 100644 --- a/common/src/main/java/org/tron/common/utils/TimeoutInterceptor.java +++ b/common/src/main/java/org/tron/common/utils/TimeoutInterceptor.java @@ -6,8 +6,10 @@ import io.grpc.ClientInterceptor; import io.grpc.MethodDescriptor; import java.util.concurrent.TimeUnit; +import lombok.extern.slf4j.Slf4j; +@Slf4j(topic = "grpcClient") public class TimeoutInterceptor implements ClientInterceptor { private final long timeout; @@ -24,7 +26,8 @@ public ClientCall interceptCall( MethodDescriptor method, CallOptions callOptions, Channel next) { - return next.newCall(method, - callOptions.withDeadlineAfter(timeout, TimeUnit.MILLISECONDS)); + CallOptions options = callOptions.withDeadlineAfter(timeout, TimeUnit.MILLISECONDS); + logger.debug("Set options {} for method {}", options, method.getFullMethodName()); + return next.newCall(method, options); } } diff --git a/framework/build.gradle b/framework/build.gradle index 59d070e066d..8b91f8a4037 100644 --- a/framework/build.gradle +++ b/framework/build.gradle @@ -44,6 +44,7 @@ dependencies { implementation 'org.eclipse.jetty:jetty-server:9.4.57.v20241219' implementation 'org.eclipse.jetty:jetty-servlet:9.4.57.v20241219' implementation 'com.alibaba:fastjson:1.2.83' + implementation group: 'io.perfmark', name: 'perfmark-api', version: '0.27.0' // end http // https://mvnrepository.com/artifact/com.github.briandilley.jsonrpc4j/jsonrpc4j @@ -104,6 +105,176 @@ run { } } +def jdkVersion = JavaVersion.current().majorVersion.toInteger() +def debugAddress = jdkVersion >= 9 ? "*:5050" : "5050" + +tasks.register('solidityNodeGroupTests', Test) { + retry { + maxRetries = 5 + maxFailures = 20 + } + filter { + includeTestsMatching "org.tron.core.services.filter.LiteFnQueryGrpcInterceptorTest" + includeTestsMatching "org.tron.core.services.filter.LiteFnQueryHttpFilterTest" + includeTestsMatching "org.tron.core.services.filter.RpcApiAccessInterceptorTest" + includeTestsMatching "org.tron.core.services.http.BroadcastServletTest" + includeTestsMatching "org.tron.core.services.http.ClearABIServletTest" + includeTestsMatching "org.tron.core.services.http.CreateAccountServletTest" + includeTestsMatching "org.tron.core.services.http.CreateAssetIssueServletTest" + includeTestsMatching "org.tron.core.services.http.CreateSpendAuthSigServletTest" + includeTestsMatching "org.tron.core.services.http.CreateWitnessServletTest" + includeTestsMatching "org.tron.core.services.http.GetAccountByIdServletTest" + includeTestsMatching "org.tron.core.services.http.GetAssetIssueListServletTest" + includeTestsMatching "org.tron.core.services.http.GetBandwidthPricesServletTest" + includeTestsMatching "org.tron.core.services.http.GetBlockByIdServletTest" + includeTestsMatching "org.tron.core.services.http.GetBlockByNumServletTest" + includeTestsMatching "org.tron.core.services.http.GetBrokerageServletTest" + includeTestsMatching "org.tron.core.services.http.GetEnergyPricesServletTest" + includeTestsMatching "org.tron.core.services.http.GetMemoFeePricesServletTest" + includeTestsMatching "org.tron.core.services.http.GetNowBlockServletTest" + includeTestsMatching "org.tron.core.services.http.GetRewardServletTest" + includeTestsMatching "org.tron.core.services.http.GetTransactionInfoByBlockNumServletTest" + includeTestsMatching "org.tron.core.services.http.GetTransactionInfoByIdServletTest" + includeTestsMatching "org.tron.core.services.http.GetTransactionListFromPendingServletTest" + includeTestsMatching "org.tron.core.services.http.HttpServletTest" + includeTestsMatching "org.tron.core.services.http.JsonFormatTest" + includeTestsMatching "org.tron.core.services.http.ListNodesServletTest" + includeTestsMatching "org.tron.core.services.http.ListProposalsServletTest" + includeTestsMatching "org.tron.core.services.http.TriggerSmartContractServletTest" + includeTestsMatching "org.tron.core.services.http.UpdateAccountServletTest" + includeTestsMatching "org.tron.core.services.http.UtilMockTest" + includeTestsMatching "org.tron.core.services.http.UtilTest" + includeTestsMatching "org.tron.core.services.http.solidity.GetTransactionByIdSolidityServletTest" + includeTestsMatching "org.tron.core.services.interfaceOnPBFT.http.GetBandwidthPricesOnPBFTServletTest" + includeTestsMatching "org.tron.core.services.interfaceOnPBFT.http.GetEnergyPricesOnPBFTServletTest" + includeTestsMatching "org.tron.core.services.interfaceOnSolidity.http.GetBandwidthPricesOnSolidityServletTest" + includeTestsMatching "org.tron.core.services.interfaceOnSolidity.http.GetEnergyPricesOnSolidityServletTest" + includeTestsMatching "org.tron.core.services.jsonrpc.BlockResultTest" + includeTestsMatching "org.tron.core.services.jsonrpc.BuildArgumentsTest" + includeTestsMatching "org.tron.core.services.jsonrpc.CallArgumentsTest" + includeTestsMatching "org.tron.core.services.jsonrpc.JsonRpcErrorResolverTest" + includeTestsMatching "org.tron.core.services.jsonrpc.TransactionReceiptTest" + includeTestsMatching "org.tron.core.services.jsonrpc.TransactionResultTest" + includeTestsMatching "org.tron.core.services.ratelimiter.GlobalRateLimiterTest" + includeTestsMatching "org.tron.core.services.ratelimiter.RuntimeDataTest" + includeTestsMatching "org.tron.core.services.ratelimiter.adaptor.AdaptorTest" + includeTestsMatching "org.tron.core.services.stop.BlockHeightStopTest" + includeTestsMatching "org.tron.core.services.stop.BlockSyncCountStopTest" + includeTestsMatching "org.tron.core.services.stop.BlockTimeStopTest" + includeTestsMatching "org.tron.core.tire.TrieTest" + includeTestsMatching "org.tron.core.witness.ProposalControllerTest" + includeTestsMatching "org.tron.core.witness.WitnessControllerTest" + includeTestsMatching "org.tron.core.zksnark.LibrustzcashTest" + includeTestsMatching "org.tron.core.zksnark.MerkleContainerTest" + includeTestsMatching "org.tron.core.zksnark.MerkleTreeTest" + includeTestsMatching "org.tron.core.zksnark.NoteEncDecryTest" + includeTestsMatching "org.tron.core.zksnark.SaplingNoteTest" + includeTestsMatching "org.tron.core.zksnark.SendCoinShieldTest" + includeTestsMatching "org.tron.core.zksnark.ShieldedReceiveTest" + includeTestsMatching "org.tron.keystore.CredentialsTest" + includeTestsMatching "org.tron.keystore.WalletFileTest" + includeTestsMatching "org.tron.keystroe.CredentialsTest" + includeTestsMatching "org.tron.program.AccountVoteWitnessTest" + includeTestsMatching "org.tron.program.SolidityNodeTest" + } + + exclude { element -> + element.file.name.toLowerCase().contains('leveldb') + } + filter { + excludeTestsMatching '*.*leveldb*' + excludeTestsMatching '*.*Leveldb*' + excludeTestsMatching '*.*LevelDB*' + excludeTestsMatching '*.*LevelDb*' + } + + testLogging { + events "passed", "skipped", "failed" + exceptionFormat "full" + showStandardStreams = false + } + + jacoco { + destinationFile = file("$buildDir/jacoco/jacocoTest.exec") + classDumpDir = file("$buildDir/jacoco/classpathdumps") + } + + maxHeapSize = "1024m" + doFirst { + // Restart the JVM after every 100 tests to avoid memory leaks and ensure test isolation + forkEvery = 100 + jvmArgs "-XX:MetaspaceSize=128m","-XX:MaxMetaspaceSize=256m", "-XX:+UseG1GC" , "-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=${debugAddress}" + } +} + +tasks.register('rpcApiServicesGroupTests', Test) { + retry { + maxRetries = 5 + maxFailures = 20 + } + filter { + includeTestsMatching "org.tron.core.net.MessageTest" + includeTestsMatching "org.tron.core.net.NodeTest" + includeTestsMatching "org.tron.core.net.P2pEventHandlerImplTest" + includeTestsMatching "org.tron.core.net.P2pRateLimiterTest" + includeTestsMatching "org.tron.core.net.TronNetDelegateTest" + includeTestsMatching "org.tron.core.net.messagehandler.BlockMsgHandlerTest" + includeTestsMatching "org.tron.core.net.messagehandler.ChainInventoryMsgHandlerTest" + includeTestsMatching "org.tron.core.net.messagehandler.FetchInvDataMsgHandlerTest" + includeTestsMatching "org.tron.core.net.messagehandler.InventoryMsgHandlerTest" + includeTestsMatching "org.tron.core.net.messagehandler.MessageHandlerTest" + includeTestsMatching "org.tron.core.net.messagehandler.PbftDataSyncHandlerTest" + includeTestsMatching "org.tron.core.net.messagehandler.PbftMsgHandlerTest" + includeTestsMatching "org.tron.core.net.messagehandler.SyncBlockChainMsgHandlerTest" + includeTestsMatching "org.tron.core.net.messagehandler.TransactionsMsgHandlerTest" + includeTestsMatching "org.tron.core.net.peer.PeerConnectionTest" + includeTestsMatching "org.tron.core.net.peer.PeerManagerTest" + includeTestsMatching "org.tron.core.net.peer.PeerStatusCheckMockTest" + includeTestsMatching "org.tron.core.net.peer.PeerStatusCheckTest" + includeTestsMatching "org.tron.core.net.service.nodepersist.DBNodeTest" + includeTestsMatching "org.tron.core.net.services.AdvServiceTest" + includeTestsMatching "org.tron.core.net.services.EffectiveCheckServiceTest" + includeTestsMatching "org.tron.core.net.services.HandShakeServiceTest" + includeTestsMatching "org.tron.core.net.services.RelayServiceTest" + includeTestsMatching "org.tron.core.net.services.ResilienceServiceTest" + includeTestsMatching "org.tron.core.net.services.SyncServiceTest" + includeTestsMatching "org.tron.core.net.services.TronStatsManagerTest" + includeTestsMatching "org.tron.core.pbft.PbftApiTest" + includeTestsMatching "org.tron.core.pbft.PbftTest" + includeTestsMatching "org.tron.core.services.RpcApiServicesTest" + + } + + exclude { element -> + element.file.name.toLowerCase().contains('leveldb') + } + filter { + excludeTestsMatching '*.*leveldb*' + excludeTestsMatching '*.*Leveldb*' + excludeTestsMatching '*.*LevelDB*' + excludeTestsMatching '*.*LevelDb*' + } + + + testLogging { + events "passed", "skipped", "failed" + exceptionFormat "full" + showStandardStreams = false + } + + jacoco { + destinationFile = file("$buildDir/jacoco/jacocoTest.exec") + classDumpDir = file("$buildDir/jacoco/classpathdumps") + } + + maxHeapSize = "1024m" + doFirst { + // Restart the JVM after every 100 tests to avoid memory leaks and ensure test isolation + forkEvery = 100 + jvmArgs "-XX:MetaspaceSize=128m","-XX:MaxMetaspaceSize=256m", "-XX:+UseG1GC" , "-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=${debugAddress}" + } +} + test { retry { maxRetries = 5 @@ -111,21 +282,22 @@ test { } testLogging { exceptionFormat = 'full' + // showStandardStreams = true } jacoco { destinationFile = file("$buildDir/jacoco/jacocoTest.exec") classDumpDir = file("$buildDir/jacoco/classpathdumps") } if (rootProject.archInfo.isArm64) { - exclude { element -> - element.file.name.toLowerCase().contains('leveldb') - } - filter { - excludeTestsMatching '*.*leveldb*' - excludeTestsMatching '*.*Leveldb*' - excludeTestsMatching '*.*LevelDB*' - excludeTestsMatching '*.*LevelDb*' - } + exclude { element -> + element.file.name.toLowerCase().contains('leveldb') + } + filter { + excludeTestsMatching '*.*leveldb*' + excludeTestsMatching '*.*Leveldb*' + excludeTestsMatching '*.*LevelDB*' + excludeTestsMatching '*.*LevelDb*' + } } if (isWindows()) { exclude '**/ShieldedTransferActuatorTest.class' @@ -140,7 +312,7 @@ test { doFirst { // Restart the JVM after every 100 tests to avoid memory leaks and ensure test isolation forkEvery = 100 - jvmArgs "-XX:MetaspaceSize=128m","-XX:MaxMetaspaceSize=256m", "-XX:+UseG1GC" + // jvmArgs "-XX:MetaspaceSize=128m","-XX:MaxMetaspaceSize=256m", "-XX:+UseG1GC" , "-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=${debugAddress}" } } diff --git a/framework/src/main/java/io/grpc/internal/ClientCallImpl.java b/framework/src/main/java/io/grpc/internal/ClientCallImpl.java new file mode 100644 index 00000000000..a5b699a57b9 --- /dev/null +++ b/framework/src/main/java/io/grpc/internal/ClientCallImpl.java @@ -0,0 +1,820 @@ +/* + * Copyright 2014 The gRPC 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 io.grpc.internal; + +import static com.google.common.base.Preconditions.checkArgument; +import static com.google.common.base.Preconditions.checkNotNull; +import static com.google.common.base.Preconditions.checkState; +import static com.google.common.util.concurrent.MoreExecutors.directExecutor; +import static io.grpc.ClientStreamTracer.NAME_RESOLUTION_DELAYED; +import static io.grpc.Contexts.statusFromCancelled; +import static io.grpc.Status.DEADLINE_EXCEEDED; +import static io.grpc.internal.GrpcUtil.CONTENT_ACCEPT_ENCODING_KEY; +import static io.grpc.internal.GrpcUtil.CONTENT_ENCODING_KEY; +import static io.grpc.internal.GrpcUtil.CONTENT_LENGTH_KEY; +import static io.grpc.internal.GrpcUtil.MESSAGE_ACCEPT_ENCODING_KEY; +import static io.grpc.internal.GrpcUtil.MESSAGE_ENCODING_KEY; + +import com.google.common.annotations.VisibleForTesting; +import com.google.common.base.MoreObjects; +import io.grpc.Attributes; +import io.grpc.CallOptions; +import io.grpc.ClientCall; +import io.grpc.ClientStreamTracer; +import io.grpc.Codec; +import io.grpc.Compressor; +import io.grpc.CompressorRegistry; +import io.grpc.Context; +import io.grpc.Context.CancellationListener; +import io.grpc.Deadline; +import io.grpc.DecompressorRegistry; +import io.grpc.InternalConfigSelector; +import io.grpc.InternalDecompressorRegistry; +import io.grpc.Metadata; +import io.grpc.MethodDescriptor; +import io.grpc.MethodDescriptor.MethodType; +import io.grpc.Status; +import io.grpc.internal.ManagedChannelServiceConfig.MethodInfo; +import io.perfmark.Link; +import io.perfmark.PerfMark; +import io.perfmark.Tag; +import io.perfmark.TaskCloseable; +import java.io.InputStream; +import java.nio.charset.Charset; +import java.util.Locale; +import java.util.concurrent.CancellationException; +import java.util.concurrent.Executor; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.ScheduledFuture; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.TimeoutException; +import javax.annotation.Nullable; +import lombok.extern.slf4j.Slf4j; + +/** + * Implementation of {@link ClientCall}. + */ +@Slf4j +final class ClientCallImpl extends ClientCall { + + private static final byte[] FULL_STREAM_DECOMPRESSION_ENCODINGS + = "gzip".getBytes(Charset.forName("US-ASCII")); + private static final double NANO_TO_SECS = 1.0 * TimeUnit.SECONDS.toNanos(1); + + private final MethodDescriptor method; + private final Tag tag; + private final Executor callExecutor; + private final boolean callExecutorIsDirect; + private final CallTracer channelCallsTracer; + private final Context context; + private CancellationHandler cancellationHandler; + private final boolean unaryRequest; + private CallOptions callOptions; + private ClientStream stream; + private boolean cancelCalled; + private boolean halfCloseCalled; + private final ClientStreamProvider clientStreamProvider; + private final ScheduledExecutorService deadlineCancellationExecutor; + private boolean fullStreamDecompression; + private DecompressorRegistry decompressorRegistry = DecompressorRegistry.getDefaultInstance(); + private CompressorRegistry compressorRegistry = CompressorRegistry.getDefaultInstance(); + + ClientCallImpl( + MethodDescriptor method, Executor executor, CallOptions callOptions, + ClientStreamProvider clientStreamProvider, + ScheduledExecutorService deadlineCancellationExecutor, + CallTracer channelCallsTracer, + // TODO(zdapeng): remove this arg + @Nullable InternalConfigSelector configSelector) { + this.method = method; + // TODO(carl-mastrangelo): consider moving this construction to ManagedChannelImpl. + this.tag = PerfMark.createTag(method.getFullMethodName(), System.identityHashCode(this)); + // If we know that the executor is a direct executor, we don't need to wrap it with a + // SerializingExecutor. This is purely for performance reasons. + // See https://github.com/grpc/grpc-java/issues/368 + if (executor == directExecutor()) { + this.callExecutor = new SerializeReentrantCallsDirectExecutor(); + callExecutorIsDirect = true; + } else { + this.callExecutor = new SerializingExecutor(executor); + callExecutorIsDirect = false; + } + logger.debug("Using call executor: {}", this.callExecutor.getClass().getName()); + this.channelCallsTracer = channelCallsTracer; + // Propagate the context from the thread which initiated the call to all callbacks. + this.context = Context.current(); + this.unaryRequest = method.getType() == MethodType.UNARY + || method.getType() == MethodType.SERVER_STREAMING; + this.callOptions = callOptions; + this.clientStreamProvider = clientStreamProvider; + this.deadlineCancellationExecutor = deadlineCancellationExecutor; + PerfMark.event("ClientCall.", tag); + logger.debug("Created ClientCall for method {}", method.getFullMethodName()); + } + + /** + * Provider of {@link ClientStream}s. + */ + interface ClientStreamProvider { + ClientStream newStream( + MethodDescriptor method, + CallOptions callOptions, + Metadata headers, + Context context); + } + + ClientCallImpl setFullStreamDecompression(boolean fullStreamDecompression) { + this.fullStreamDecompression = fullStreamDecompression; + return this; + } + + ClientCallImpl setDecompressorRegistry(DecompressorRegistry decompressorRegistry) { + this.decompressorRegistry = decompressorRegistry; + return this; + } + + ClientCallImpl setCompressorRegistry(CompressorRegistry compressorRegistry) { + this.compressorRegistry = compressorRegistry; + return this; + } + + @VisibleForTesting + static void prepareHeaders( + Metadata headers, + DecompressorRegistry decompressorRegistry, + Compressor compressor, + boolean fullStreamDecompression) { + headers.discardAll(CONTENT_LENGTH_KEY); + headers.discardAll(MESSAGE_ENCODING_KEY); + if (compressor != Codec.Identity.NONE) { + headers.put(MESSAGE_ENCODING_KEY, compressor.getMessageEncoding()); + } + + headers.discardAll(MESSAGE_ACCEPT_ENCODING_KEY); + byte[] advertisedEncodings = + InternalDecompressorRegistry.getRawAdvertisedMessageEncodings(decompressorRegistry); + if (advertisedEncodings.length != 0) { + headers.put(MESSAGE_ACCEPT_ENCODING_KEY, advertisedEncodings); + } + + headers.discardAll(CONTENT_ENCODING_KEY); + headers.discardAll(CONTENT_ACCEPT_ENCODING_KEY); + if (fullStreamDecompression) { + headers.put(CONTENT_ACCEPT_ENCODING_KEY, FULL_STREAM_DECOMPRESSION_ENCODINGS); + } + logger.debug("Prepared headers: {}", headers); + } + + @Override + public void start(Listener observer, Metadata headers) { + try (TaskCloseable ignore = PerfMark.traceTask("ClientCall.start")) { + logger.debug("Starting call for method {}", method.getFullMethodName()); + PerfMark.attachTag(tag); + startInternal(observer, headers); + logger.debug("Started call for method {}", method.getFullMethodName()); + } + } + + private void startInternal(Listener observer, Metadata headers) { + checkState(stream == null, "Already started"); + checkState(!cancelCalled, "call was cancelled"); + checkNotNull(observer, "observer"); + checkNotNull(headers, "headers"); + + if (context.isCancelled()) { + // Context is already cancelled so no need to create a real stream, just notify the observer + // of cancellation via callback on the executor + stream = NoopClientStream.INSTANCE; + final Listener finalObserver = observer; + class ClosedByContext extends ContextRunnable { + ClosedByContext() { + super(context); + } + + @Override + public void runInContext() { + closeObserver(finalObserver, statusFromCancelled(context), new Metadata()); + } + } + + callExecutor.execute(new ClosedByContext()); + logger.debug("Call cancelled by context before start"); + return; + } + applyMethodConfig(); + final String compressorName = callOptions.getCompressor(); + Compressor compressor; + if (compressorName != null) { + compressor = compressorRegistry.lookupCompressor(compressorName); + if (compressor == null) { + stream = NoopClientStream.INSTANCE; + final Listener finalObserver = observer; + class ClosedByNotFoundCompressor extends ContextRunnable { + ClosedByNotFoundCompressor() { + super(context); + } + + @Override + public void runInContext() { + closeObserver( + finalObserver, + Status.INTERNAL.withDescription( + String.format("Unable to find compressor by name %s", compressorName)), + new Metadata()); + } + } + + callExecutor.execute(new ClosedByNotFoundCompressor()); + logger.debug("Call failed to start due to unknown compressor: {}", compressorName); + return; + } + } else { + compressor = Codec.Identity.NONE; + } + prepareHeaders(headers, decompressorRegistry, compressor, fullStreamDecompression); + + Deadline effectiveDeadline = effectiveDeadline(); + boolean contextIsDeadlineSource = effectiveDeadline != null + && effectiveDeadline.equals(context.getDeadline()); + cancellationHandler = new CancellationHandler(effectiveDeadline, contextIsDeadlineSource); + boolean deadlineExceeded = effectiveDeadline != null && cancellationHandler.remainingNanos <= 0; + if (!deadlineExceeded) { + stream = clientStreamProvider.newStream(method, callOptions, headers, context); + logger.debug("Created new stream for method {}", method.getFullMethodName()); + } else { + ClientStreamTracer[] tracers = + GrpcUtil.getClientStreamTracers(callOptions, headers, 0, false); + String deadlineName = contextIsDeadlineSource ? "Context" : "CallOptions"; + Long nameResolutionDelay = callOptions.getOption(NAME_RESOLUTION_DELAYED); + String description = String.format( + "ClientCall started after %s deadline was exceeded %.9f seconds ago. " + + "Name resolution delay %.9f seconds.", deadlineName, + cancellationHandler.remainingNanos / NANO_TO_SECS, + nameResolutionDelay == null ? 0 : nameResolutionDelay / NANO_TO_SECS); + stream = new FailingClientStream(DEADLINE_EXCEEDED.withDescription(description), tracers); + logger.debug("Not creating stream for method {} as deadline already exceeded", + method.getFullMethodName()); + } + + if (callExecutorIsDirect) { + stream.optimizeForDirectExecutor(); + } + if (callOptions.getAuthority() != null) { + stream.setAuthority(callOptions.getAuthority()); + } + if (callOptions.getMaxInboundMessageSize() != null) { + stream.setMaxInboundMessageSize(callOptions.getMaxInboundMessageSize()); + } + if (callOptions.getMaxOutboundMessageSize() != null) { + stream.setMaxOutboundMessageSize(callOptions.getMaxOutboundMessageSize()); + } + if (effectiveDeadline != null) { + stream.setDeadline(effectiveDeadline); + } + stream.setCompressor(compressor); + if (fullStreamDecompression) { + stream.setFullStreamDecompression(fullStreamDecompression); + } + stream.setDecompressorRegistry(decompressorRegistry); + channelCallsTracer.reportCallStarted(); + stream.start(new ClientStreamListenerImpl(observer)); + + // Delay any sources of cancellation after start(), because most of the transports are broken if + // they receive cancel before start. Issue #1343 has more details + + // Propagate later Context cancellation to the remote side. + cancellationHandler.setUp(); + } + + private void applyMethodConfig() { + MethodInfo info = callOptions.getOption(MethodInfo.KEY); + if (info == null) { + return; + } + if (info.timeoutNanos != null) { + Deadline newDeadline = Deadline.after(info.timeoutNanos, TimeUnit.NANOSECONDS); + Deadline existingDeadline = callOptions.getDeadline(); + // If the new deadline is sooner than the existing deadline, swap them. + if (existingDeadline == null || newDeadline.compareTo(existingDeadline) < 0) { + callOptions = callOptions.withDeadline(newDeadline); + } + } + if (info.waitForReady != null) { + callOptions = + info.waitForReady ? callOptions.withWaitForReady() : callOptions.withoutWaitForReady(); + } + if (info.maxInboundMessageSize != null) { + Integer existingLimit = callOptions.getMaxInboundMessageSize(); + if (existingLimit != null) { + callOptions = + callOptions.withMaxInboundMessageSize( + Math.min(existingLimit, info.maxInboundMessageSize)); + } else { + callOptions = callOptions.withMaxInboundMessageSize(info.maxInboundMessageSize); + } + } + if (info.maxOutboundMessageSize != null) { + Integer existingLimit = callOptions.getMaxOutboundMessageSize(); + if (existingLimit != null) { + callOptions = + callOptions.withMaxOutboundMessageSize( + Math.min(existingLimit, info.maxOutboundMessageSize)); + } else { + callOptions = callOptions.withMaxOutboundMessageSize(info.maxOutboundMessageSize); + } + } + logger.debug("Applied method config: {}, updated CallOptions: {}", info, callOptions); + } + + private final class CancellationHandler implements Runnable, CancellationListener { + private final boolean contextIsDeadlineSource; + private final boolean hasDeadline; + private final long remainingNanos; + private volatile ScheduledFuture deadlineCancellationFuture; + private volatile boolean tearDownCalled; + + CancellationHandler(Deadline deadline, boolean contextIsDeadlineSource) { + this.contextIsDeadlineSource = contextIsDeadlineSource; + if (deadline == null) { + hasDeadline = false; + remainingNanos = 0; + } else { + hasDeadline = true; + remainingNanos = deadline.timeRemaining(TimeUnit.NANOSECONDS); + } + } + + void setUp() { + if (tearDownCalled) { + return; + } + if (hasDeadline + // If the context has the effective deadline, we don't need to schedule an extra task. + && !contextIsDeadlineSource + // If the channel has been terminated, we don't need to schedule an extra task. + && deadlineCancellationExecutor != null) { + deadlineCancellationFuture = deadlineCancellationExecutor.schedule( + new LogExceptionRunnable(this), remainingNanos, TimeUnit.NANOSECONDS); + } + context.addListener(this, directExecutor()); + logger.debug("CancellationHandler set up"); + if (tearDownCalled) { + // Race detected! Re-run to make sure the future is cancelled and context listener removed + tearDown(); + } + } + + // May be called multiple times, and race with setUp() + void tearDown() { + tearDownCalled = true; + ScheduledFuture deadlineCancellationFuture = this.deadlineCancellationFuture; + if (deadlineCancellationFuture != null) { + deadlineCancellationFuture.cancel(false); + } + context.removeListener(this); + logger.debug("CancellationHandler tear down"); + } + + @Override + public void cancelled(Context context) { + if (hasDeadline && contextIsDeadlineSource + && context.cancellationCause() instanceof TimeoutException) { + stream.cancel(formatDeadlineExceededStatus()); + logger.debug("Call cancelled by context deadline"); + return; + } + stream.cancel(statusFromCancelled(context)); + logger.debug("Call cancelled by context"); + } + + @Override + public void run() { + stream.cancel(formatDeadlineExceededStatus()); + logger.debug("Call cancelled by call options deadline"); + } + + Status formatDeadlineExceededStatus() { + // DelayedStream.cancel() is safe to call from a thread that is different from where the + // stream is created. + long seconds = Math.abs(remainingNanos) / TimeUnit.SECONDS.toNanos(1); + long nanos = Math.abs(remainingNanos) % TimeUnit.SECONDS.toNanos(1); + + StringBuilder buf = new StringBuilder(); + buf.append(contextIsDeadlineSource ? "Context" : "CallOptions"); + buf.append(" deadline exceeded after "); + if (remainingNanos < 0) { + buf.append('-'); + } + buf.append(seconds); + buf.append(String.format(Locale.US, ".%09d", nanos)); + buf.append("s. "); + Long nsDelay = callOptions.getOption(NAME_RESOLUTION_DELAYED); + buf.append(String.format(Locale.US, "Name resolution delay %.9f seconds.", + nsDelay == null ? 0 : nsDelay / NANO_TO_SECS)); + if (stream != null) { + InsightBuilder insight = new InsightBuilder(); + stream.appendTimeoutInsight(insight); + buf.append(" "); + buf.append(insight); + } + return DEADLINE_EXCEEDED.withDescription(buf.toString()); + } + } + + @Nullable + private Deadline effectiveDeadline() { + // Call options and context are immutable, so we don't need to cache the deadline. + return min(callOptions.getDeadline(), context.getDeadline()); + } + + @Nullable + private static Deadline min(@Nullable Deadline deadline0, @Nullable Deadline deadline1) { + if (deadline0 == null) { + return deadline1; + } + if (deadline1 == null) { + return deadline0; + } + return deadline0.minimum(deadline1); + } + + @Override + public void request(int numMessages) { + try (TaskCloseable ignore = PerfMark.traceTask("ClientCall.request")) { + PerfMark.attachTag(tag); + checkState(stream != null, "Not started"); + checkArgument(numMessages >= 0, "Number requested must be non-negative"); + stream.request(numMessages); + logger.debug("Requested {} messages", numMessages); + } + } + + @Override + public void cancel(@Nullable String message, @Nullable Throwable cause) { + try (TaskCloseable ignore = PerfMark.traceTask("ClientCall.cancel")) { + PerfMark.attachTag(tag); + cancelInternal(message, cause); + logger.debug("Cancelled call with message: {}", message); + } + } + + private void cancelInternal(@Nullable String message, @Nullable Throwable cause) { + if (message == null && cause == null) { + cause = new CancellationException("Cancelled without a message or cause"); + logger.warn("Cancelling without a message or cause is suboptimal", cause); + } + if (cancelCalled) { + return; + } + cancelCalled = true; + try { + // Cancel is called in exception handling cases, so it may be the case that the + // stream was never successfully created or start has never been called. + if (stream != null) { + Status status = Status.CANCELLED; + if (message != null) { + status = status.withDescription(message); + } else { + status = status.withDescription("Call cancelled without message"); + } + if (cause != null) { + status = status.withCause(cause); + } + stream.cancel(status); + } + } finally { + // start() might not have been called + if (cancellationHandler != null) { + cancellationHandler.tearDown(); + } + } + } + + @Override + public void halfClose() { + try (TaskCloseable ignore = PerfMark.traceTask("ClientCall.halfClose")) { + PerfMark.attachTag(tag); + halfCloseInternal(); + logger.debug("Half-closed call for method {}", method.getFullMethodName()); + } + } + + private void halfCloseInternal() { + checkState(stream != null, "Not started"); + checkState(!cancelCalled, "call was cancelled"); + checkState(!halfCloseCalled, "call already half-closed"); + halfCloseCalled = true; + stream.halfClose(); + logger.debug("Half-closed the stream"); + } + + @Override + public void sendMessage(ReqT message) { + try (TaskCloseable ignore = PerfMark.traceTask("ClientCall.sendMessage")) { + PerfMark.attachTag(tag); + sendMessageInternal(message); + logger.debug("Sent message for method {}", method.getFullMethodName()); + } + } + + private void sendMessageInternal(ReqT message) { + checkState(stream != null, "Not started"); + checkState(!cancelCalled, "call was cancelled"); + checkState(!halfCloseCalled, "call was half-closed"); + try { + if (stream instanceof RetriableStream) { + @SuppressWarnings("unchecked") + RetriableStream retriableStream = (RetriableStream) stream; + retriableStream.sendMessage(message); + } else { + stream.writeMessage(method.streamRequest(message)); + } + } catch (RuntimeException e) { + stream.cancel(Status.CANCELLED.withCause(e).withDescription("Failed to stream message")); + return; + } catch (Error e) { + stream.cancel(Status.CANCELLED.withDescription("Client sendMessage() failed with Error")); + throw e; + } + // For unary requests, we don't flush since we know that halfClose should be coming soon. This + // allows us to piggy-back the END_STREAM=true on the last message frame without opening the + // possibility of broken applications forgetting to call halfClose without noticing. + if (!unaryRequest) { + stream.flush(); + logger.debug("Flushed the stream after sending message"); + } + } + + @Override + public void setMessageCompression(boolean enabled) { + checkState(stream != null, "Not started"); + stream.setMessageCompression(enabled); + logger.debug("Set message compression to {}", enabled); + } + + @Override + public boolean isReady() { + if (halfCloseCalled) { + return false; + } + logger.debug("Checked isReady: {}", stream.isReady()); + return stream.isReady(); + } + + @Override + public Attributes getAttributes() { + if (stream != null) { + return stream.getAttributes(); + } + return Attributes.EMPTY; + } + + private void closeObserver(Listener observer, Status status, Metadata trailers) { + try { + observer.onClose(status, trailers); + logger.debug("Closed observer with status: {}", status); + } catch (RuntimeException ex) { + logger.warn("Exception thrown by onClose() in ClientCall", ex); + } + } + + @Override + public String toString() { + return MoreObjects.toStringHelper(this).add("method", method).toString(); + } + + private class ClientStreamListenerImpl implements ClientStreamListener { + private final Listener observer; + private Status exceptionStatus; + + public ClientStreamListenerImpl(Listener observer) { + this.observer = checkNotNull(observer, "observer"); + } + + /** + * Cancels call and schedules onClose() notification. May only be called from the application + * thread. + */ + private void exceptionThrown(Status status) { + // Since each RPC can have its own executor, we can only call onClose() when we are sure there + // will be no further callbacks. We set the status here and overwrite the onClose() details + // when it arrives. + exceptionStatus = status; + stream.cancel(status); + logger.debug("Exception thrown in call: {}", status); + } + + @Override + public void headersRead(final Metadata headers) { + try (TaskCloseable ignore = PerfMark.traceTask("ClientStreamListener.headersRead")) { + logger.debug("Headers read for call start {}", method.getFullMethodName()); + PerfMark.attachTag(tag); + final Link link = PerfMark.linkOut(); + final class HeadersRead extends ContextRunnable { + HeadersRead() { + super(context); + } + + @Override + public void runInContext() { + try (TaskCloseable ignore = PerfMark.traceTask("ClientCall$Listener.headersRead")) { + PerfMark.attachTag(tag); + PerfMark.linkIn(link); + runInternal(); + logger.debug("headersRead executed: {}", method.getFullMethodName()); + } + } + + private void runInternal() { + if (exceptionStatus != null) { + return; + } + try { + observer.onHeaders(headers); + } catch (Throwable t) { + exceptionThrown( + Status.CANCELLED.withCause(t).withDescription("Failed to read headers")); + } + } + } + + callExecutor.execute(new HeadersRead()); + logger.debug("Read headers for call end {}", method.getFullMethodName()); + } + } + + @Override + public void messagesAvailable(final MessageProducer producer) { + try (TaskCloseable ignore = PerfMark.traceTask("ClientStreamListener.messagesAvailable")) { + logger.debug("Messages available for call start {}", method.getFullMethodName()); + PerfMark.attachTag(tag); + final Link link = PerfMark.linkOut(); + final class MessagesAvailable extends ContextRunnable { + MessagesAvailable() { + super(context); + } + + @Override + public void runInContext() { + try (TaskCloseable ignore = + PerfMark.traceTask("ClientCall$Listener.messagesAvailable")) { + PerfMark.attachTag(tag); + PerfMark.linkIn(link); + runInternal(); + logger.debug("MessagesAvailable executed {}", method.getFullMethodName()); + } + } + + private void runInternal() { + if (exceptionStatus != null) { + GrpcUtil.closeQuietly(producer); + return; + } + try { + InputStream message; + while ((message = producer.next()) != null) { + try { + observer.onMessage(method.parseResponse(message)); + } catch (Throwable t) { + GrpcUtil.closeQuietly(message); + throw t; + } + message.close(); + } + } catch (Throwable t) { + GrpcUtil.closeQuietly(producer); + exceptionThrown( + Status.CANCELLED.withCause(t).withDescription("Failed to read message.")); + } + } + } + + callExecutor.execute(new MessagesAvailable()); + logger.debug("Messages available for call end {}", method.getFullMethodName()); + } + } + + @Override + public void closed(Status status, RpcProgress rpcProgress, Metadata trailers) { + try (TaskCloseable ignore = PerfMark.traceTask("ClientStreamListener.closed")) { + logger.debug("Call closed start {} with status {}", method.getFullMethodName(), status); + PerfMark.attachTag(tag); + closedInternal(status, rpcProgress, trailers); + logger.debug("Call closed end {}", method.getFullMethodName()); + } + } + + private void closedInternal( + Status status, @SuppressWarnings("unused") RpcProgress rpcProgress, Metadata trailers) { + Deadline deadline = effectiveDeadline(); + if (status.getCode() == Status.Code.CANCELLED && deadline != null) { + // When the server's deadline expires, it can only reset the stream with CANCEL and no + // description. Since our timer may be delayed in firing, we double-check the deadline and + // turn the failure into the likely more helpful DEADLINE_EXCEEDED status. + if (deadline.isExpired()) { + status = cancellationHandler.formatDeadlineExceededStatus(); + // Replace trailers to prevent mixing sources of status and trailers. + trailers = new Metadata(); + } + } + final Status savedStatus = status; + final Metadata savedTrailers = trailers; + final Link link = PerfMark.linkOut(); + final class StreamClosed extends ContextRunnable { + StreamClosed() { + super(context); + } + + @Override + public void runInContext() { + try (TaskCloseable ignore = PerfMark.traceTask("ClientCall$Listener.onClose")) { + PerfMark.attachTag(tag); + PerfMark.linkIn(link); + runInternal(); + logger.debug("StreamClosed executed {}", method.getFullMethodName()); + } + } + + private void runInternal() { + cancellationHandler.tearDown(); + Status status = savedStatus; + Metadata trailers = savedTrailers; + if (exceptionStatus != null) { + // Ideally exceptionStatus == savedStatus, as exceptionStatus was passed to cancel(). + // However the cancel is racy and this closed() may have already been queued when the + // cancellation occurred. Since other calls like onMessage() will throw away data if + // exceptionStatus != null, it is semantically essential that we _not_ use a status + // provided by the server. + status = exceptionStatus; + // Replace trailers to prevent mixing sources of status and trailers. + trailers = new Metadata(); + } + try { + closeObserver(observer, status, trailers); + } finally { + channelCallsTracer.reportCallEnded(status.isOk()); + } + } + } + + callExecutor.execute(new StreamClosed()); + } + + @Override + public void onReady() { + if (method.getType().clientSendsOneMessage()) { + return; + } + try (TaskCloseable ignore = PerfMark.traceTask("ClientStreamListener.onReady")) { + logger.debug("onReady for call start {}", method.getFullMethodName()); + PerfMark.attachTag(tag); + final Link link = PerfMark.linkOut(); + + final class StreamOnReady extends ContextRunnable { + StreamOnReady() { + super(context); + } + + @Override + public void runInContext() { + try (TaskCloseable ignore = PerfMark.traceTask("ClientCall$Listener.onReady")) { + PerfMark.attachTag(tag); + PerfMark.linkIn(link); + runInternal(); + logger.debug("onReady executed {}", method.getFullMethodName()); + } + } + + private void runInternal() { + if (exceptionStatus != null) { + return; + } + try { + observer.onReady(); + } catch (Throwable t) { + exceptionThrown( + Status.CANCELLED.withCause(t).withDescription("Failed to call onReady.")); + } + } + } + + callExecutor.execute(new StreamOnReady()); + logger.debug("onReady for call end {}", method.getFullMethodName()); + } + } + } +} diff --git a/framework/src/main/java/io/grpc/internal/Http2ClientStreamTransportState.java b/framework/src/main/java/io/grpc/internal/Http2ClientStreamTransportState.java new file mode 100644 index 00000000000..3d35471f440 --- /dev/null +++ b/framework/src/main/java/io/grpc/internal/Http2ClientStreamTransportState.java @@ -0,0 +1,276 @@ +/* + * Copyright 2014 The gRPC 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 io.grpc.internal; + +import com.google.common.base.Preconditions; +import io.grpc.CallOptions; +import io.grpc.InternalMetadata; +import io.grpc.InternalStatus; +import io.grpc.Metadata; +import io.grpc.Status; +import java.nio.charset.Charset; +import java.nio.charset.StandardCharsets; +import javax.annotation.Nullable; +import lombok.extern.slf4j.Slf4j; + +/** + * Base implementation for client streams using HTTP2 as the transport. + */ +@Slf4j +public abstract class Http2ClientStreamTransportState extends AbstractClientStream.TransportState { + + /** + * Metadata marshaller for HTTP status lines. + */ + private static final InternalMetadata.TrustedAsciiMarshaller HTTP_STATUS_MARSHALLER = + new InternalMetadata.TrustedAsciiMarshaller() { + @Override + public byte[] toAsciiString(Integer value) { + throw new UnsupportedOperationException(); + } + + /** + * RFC 7231 says status codes are 3 digits long. + * + * @see RFC 7231 + */ + @Override + public Integer parseAsciiString(byte[] serialized) { + if (serialized.length >= 3) { + return (serialized[0] - '0') * 100 + (serialized[1] - '0') * 10 + (serialized[2] - '0'); + } + throw new NumberFormatException( + "Malformed status code " + new String(serialized, InternalMetadata.US_ASCII)); + } + }; + + private static final Metadata.Key HTTP2_STATUS = InternalMetadata.keyOf(":status", + HTTP_STATUS_MARSHALLER); + + /** When non-{@code null}, {@link #transportErrorMetadata} must also be non-{@code null}. */ + private Status transportError; + private Metadata transportErrorMetadata; + private Charset errorCharset = StandardCharsets.UTF_8; + private boolean headersReceived; + + protected Http2ClientStreamTransportState( + int maxMessageSize, + StatsTraceContext statsTraceCtx, + TransportTracer transportTracer, + CallOptions options) { + super(maxMessageSize, statsTraceCtx, transportTracer, options); + } + + /** + * Called to process a failure in HTTP/2 processing. It should notify the transport to cancel the + * stream and call {@code transportReportStatus()}. + */ + protected abstract void http2ProcessingFailed( + Status status, boolean stopDelivery, Metadata trailers); + + /** + * Called by subclasses whenever {@code Headers} are received from the transport. + * + * @param headers the received headers + */ + protected void transportHeadersReceived(Metadata headers) { + logger.debug("transportHeadersReceived: {}", headers); + Preconditions.checkNotNull(headers, "headers"); + if (transportError != null) { + // Already received a transport error so just augment it. Something is really, really strange. + transportError = transportError.augmentDescription("headers: " + headers); + logger.debug("transportHeadersReceived with transportError: {}", transportError); + return; + } + try { + if (headersReceived) { + transportError = Status.INTERNAL.withDescription("Received headers twice"); + logger.debug("transportHeadersReceived with transportError: {}", transportError); + return; + } + Integer httpStatus = headers.get(HTTP2_STATUS); + if (httpStatus != null && httpStatus >= 100 && httpStatus < 200) { + // Ignore the headers. See RFC 7540 ยง8.1 + logger.debug("transportHeadersReceived received informational headers: {}", headers); + return; + } + headersReceived = true; + + transportError = validateInitialMetadata(headers); + if (transportError != null) { + logger.debug("transportHeadersReceived with transportError: {}", transportError); + return; + } + + stripTransportDetails(headers); + logger.debug("transportHeadersReceived completed successfully"); + inboundHeadersReceived(headers); + logger.debug("inboundHeadersReceived completed successfully"); + } finally { + if (transportError != null) { + // Note we don't immediately report the transport error, instead we wait for more data on + // the stream so we can accumulate more detail into the error before reporting it. + transportError = transportError.augmentDescription("headers: " + headers); + transportErrorMetadata = headers; + errorCharset = extractCharset(headers); + logger.debug("transportHeadersReceived with transportError: {}", transportError); + } + } + } + + /** + * Called by subclasses whenever a data frame is received from the transport. + * + * @param frame the received data frame + * @param endOfStream {@code true} if there will be no more data received for this stream + */ + protected void transportDataReceived(ReadableBuffer frame, boolean endOfStream) { + if (transportError != null) { + // We've already detected a transport error and now we're just accumulating more detail + // for it. + transportError = transportError.augmentDescription("DATA-----------------------------\n" + + ReadableBuffers.readAsString(frame, errorCharset)); + frame.close(); + if (transportError.getDescription().length() > 1000 || endOfStream) { + http2ProcessingFailed(transportError, false, transportErrorMetadata); + } + logger.debug("transportDataReceived with transportError: {}", transportError); + } else { + if (!headersReceived) { + frame.close(); + http2ProcessingFailed( + Status.INTERNAL.withDescription("headers not received before payload"), + false, + new Metadata()); + logger.debug("transportDataReceived without headers received"); + return; + } + int frameSize = frame.readableBytes(); + inboundDataReceived(frame); + logger.debug("transportDataReceived completed successfully"); + if (endOfStream) { + // This is a protocol violation as we expect to receive trailers. + if (frameSize > 0) { + transportError = Status.INTERNAL + .withDescription("Received unexpected EOS on non-empty DATA frame from server"); + } else { + transportError = Status.INTERNAL + .withDescription("Received unexpected EOS on empty DATA frame from server"); + } + transportErrorMetadata = new Metadata(); + transportReportStatus(transportError, false, transportErrorMetadata); + logger.debug("transportDataReceived with transportError: {}", transportError); + } + } + } + + /** + * Called by subclasses for the terminal trailer metadata on a stream. + * + * @param trailers the received terminal trailer metadata + */ + protected void transportTrailersReceived(Metadata trailers) { + logger.debug("transportTrailersReceived: {}", trailers); + Preconditions.checkNotNull(trailers, "trailers"); + if (transportError == null && !headersReceived) { + transportError = validateInitialMetadata(trailers); + if (transportError != null) { + transportErrorMetadata = trailers; + } + } + if (transportError != null) { + transportError = transportError.augmentDescription("trailers: " + trailers); + http2ProcessingFailed(transportError, false, transportErrorMetadata); + logger.debug("transportTrailersReceived with transportError: {}", transportError); + } else { + Status status = statusFromTrailers(trailers); + stripTransportDetails(trailers); + inboundTrailersReceived(trailers, status); + logger.debug("transportTrailersReceived completed successfully"); + } + } + + /** + * Extract the response status from trailers. + */ + private Status statusFromTrailers(Metadata trailers) { + Status status = trailers.get(InternalStatus.CODE_KEY); + if (status != null) { + return status.withDescription(trailers.get(InternalStatus.MESSAGE_KEY)); + } + // No status; something is broken. Try to provide a resonanable error. + if (headersReceived) { + return Status.UNKNOWN.withDescription("missing GRPC status in response"); + } + Integer httpStatus = trailers.get(HTTP2_STATUS); + if (httpStatus != null) { + status = GrpcUtil.httpStatusToGrpcStatus(httpStatus); + } else { + status = Status.INTERNAL.withDescription("missing HTTP status code"); + } + return status.augmentDescription( + "missing GRPC status, inferred error from HTTP status code"); + } + + /** + * Inspect initial headers to make sure they conform to HTTP and gRPC, returning a {@code Status} + * on failure. + * + * @return status with description of failure, or {@code null} when valid + */ + @Nullable + private Status validateInitialMetadata(Metadata headers) { + Integer httpStatus = headers.get(HTTP2_STATUS); + if (httpStatus == null) { + return Status.INTERNAL.withDescription("Missing HTTP status code"); + } + String contentType = headers.get(GrpcUtil.CONTENT_TYPE_KEY); + if (!GrpcUtil.isGrpcContentType(contentType)) { + return GrpcUtil.httpStatusToGrpcStatus(httpStatus) + .augmentDescription("invalid content-type: " + contentType); + } + return null; + } + + /** + * Inspect the raw metadata and figure out what charset is being used. + */ + private static Charset extractCharset(Metadata headers) { + String contentType = headers.get(GrpcUtil.CONTENT_TYPE_KEY); + if (contentType != null) { + String[] split = contentType.split("charset=", 2); + try { + return Charset.forName(split[split.length - 1].trim()); + } catch (Exception t) { + // Ignore and assume UTF-8 + } + } + return StandardCharsets.UTF_8; + } + + /** + * Strip HTTP transport implementation details so they don't leak via metadata into + * the application layer. + */ + private static void stripTransportDetails(Metadata metadata) { + logger.debug("Stripping transport details from metadata: {}", metadata); + metadata.discardAll(HTTP2_STATUS); + metadata.discardAll(InternalStatus.CODE_KEY); + metadata.discardAll(InternalStatus.MESSAGE_KEY); + logger.debug("Stripped transport details from metadata: {}", metadata); + } +} diff --git a/framework/src/main/java/io/grpc/internal/MessageDeframer.java b/framework/src/main/java/io/grpc/internal/MessageDeframer.java new file mode 100644 index 00000000000..04ba1a5bc14 --- /dev/null +++ b/framework/src/main/java/io/grpc/internal/MessageDeframer.java @@ -0,0 +1,558 @@ +/* + * Copyright 2014 The gRPC 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 io.grpc.internal; + +import static com.google.common.base.Preconditions.checkArgument; +import static com.google.common.base.Preconditions.checkNotNull; +import static com.google.common.base.Preconditions.checkState; + +import com.google.common.annotations.VisibleForTesting; +import io.grpc.Codec; +import io.grpc.Decompressor; +import io.grpc.Status; +import java.io.Closeable; +import java.io.FilterInputStream; +import java.io.IOException; +import java.io.InputStream; +import java.util.Locale; +import java.util.zip.DataFormatException; +import javax.annotation.Nullable; +import javax.annotation.concurrent.NotThreadSafe; +import lombok.extern.slf4j.Slf4j; + +/** + * Deframer for GRPC frames. + * + *

This class is not thread-safe. Unless otherwise stated, all calls to public methods should be + * made in the deframing thread. + */ +@NotThreadSafe +@Slf4j +public class MessageDeframer implements Closeable, Deframer { + private static final int HEADER_LENGTH = 5; + private static final int COMPRESSED_FLAG_MASK = 1; + private static final int RESERVED_MASK = 0xFE; + private static final int MAX_BUFFER_SIZE = 1024 * 1024 * 2; + + /** + * A listener of deframing events. These methods will be invoked from the deframing thread. + */ + public interface Listener { + + /** + * Called when the given number of bytes has been read from the input source of the deframer. + * This is typically used to indicate to the underlying transport that more data can be + * accepted. + * + * @param numBytes the number of bytes read from the deframer's input source. + */ + void bytesRead(int numBytes); + + /** + * Called to deliver the next complete message. + * + * @param producer single message producer wrapping the message. + */ + void messagesAvailable(StreamListener.MessageProducer producer); + + /** + * Called when the deframer closes. + * + * @param hasPartialMessage whether the deframer contained an incomplete message at closing. + */ + void deframerClosed(boolean hasPartialMessage); + + /** + * Called when a {@link #deframe(ReadableBuffer)} operation failed. + * + * @param cause the actual failure + */ + void deframeFailed(Throwable cause); + } + + private enum State { + HEADER, BODY + } + + private Listener listener; + private int maxInboundMessageSize; + private final StatsTraceContext statsTraceCtx; + private final TransportTracer transportTracer; + private Decompressor decompressor; + private GzipInflatingBuffer fullStreamDecompressor; + private byte[] inflatedBuffer; + private int inflatedIndex; + private State state = State.HEADER; + private int requiredLength = HEADER_LENGTH; + private boolean compressedFlag; + private CompositeReadableBuffer nextFrame; + private CompositeReadableBuffer unprocessed = new CompositeReadableBuffer(); + private long pendingDeliveries; + private boolean inDelivery = false; + private int currentMessageSeqNo = -1; + private int inboundBodyWireSize; + + private boolean closeWhenComplete = false; + private volatile boolean stopDelivery = false; + + /** + * Create a deframer. + * + * @param listener listener for deframer events. + * @param decompressor the compression used if a compressed frame is encountered, with + * {@code NONE} meaning unsupported + * @param maxMessageSize the maximum allowed size for received messages. + */ + public MessageDeframer( + Listener listener, + Decompressor decompressor, + int maxMessageSize, + StatsTraceContext statsTraceCtx, + TransportTracer transportTracer) { + this.listener = checkNotNull(listener, "sink"); + this.decompressor = checkNotNull(decompressor, "decompressor"); + this.maxInboundMessageSize = maxMessageSize; + this.statsTraceCtx = checkNotNull(statsTraceCtx, "statsTraceCtx"); + this.transportTracer = checkNotNull(transportTracer, "transportTracer"); + } + + void setListener(Listener listener) { + this.listener = listener; + } + + @Override + public void setMaxInboundMessageSize(int messageSize) { + maxInboundMessageSize = messageSize; + } + + @Override + public void setDecompressor(Decompressor decompressor) { + checkState(fullStreamDecompressor == null, "Already set full stream decompressor"); + this.decompressor = checkNotNull(decompressor, "Can't pass an empty decompressor"); + } + + @Override + public void setFullStreamDecompressor(GzipInflatingBuffer fullStreamDecompressor) { + checkState(decompressor == Codec.Identity.NONE, "per-message decompressor already set"); + checkState(this.fullStreamDecompressor == null, "full stream decompressor already set"); + this.fullStreamDecompressor = + checkNotNull(fullStreamDecompressor, "Can't pass a null full stream decompressor"); + unprocessed = null; + } + + @Override + public void request(int numMessages) { + checkArgument(numMessages > 0, "numMessages must be > 0"); + logger.debug("request {}", numMessages); + if (isClosed()) { + logger.debug("request {} ignored as deframer is closed", numMessages); + return; + } + pendingDeliveries += numMessages; + deliver(); + logger.debug("request {} complete", numMessages); + } + + @Override + public void deframe(ReadableBuffer data) { + logger.debug("deframe {} bytes", data.readableBytes()); + checkNotNull(data, "data"); + boolean needToCloseData = true; + try { + if (!isClosedOrScheduledToClose()) { + if (fullStreamDecompressor != null) { + fullStreamDecompressor.addGzippedBytes(data); + } else { + unprocessed.addBuffer(data); + } + needToCloseData = false; + + deliver(); + } + } finally { + if (needToCloseData) { + data.close(); + } + logger.debug("deframe complete"); + } + } + + @Override + public void closeWhenComplete() { + if (isClosed()) { + return; + } else if (isStalled()) { + close(); + } else { + closeWhenComplete = true; + } + logger.debug("closeWhenComplete complete"); + } + + /** + * Sets a flag to interrupt delivery of any currently queued messages. This may be invoked outside + * of the deframing thread, and must be followed by a call to {@link #close()} in the deframing + * thread. Without a subsequent call to {@link #close()}, the deframer may hang waiting for + * additional messages before noticing that the {@code stopDelivery} flag has been set. + */ + void stopDelivery() { + stopDelivery = true; + } + + boolean hasPendingDeliveries() { + return pendingDeliveries != 0; + } + + @Override + public void close() { + logger.debug("close start"); + if (isClosed()) { + return; + } + boolean hasPartialMessage = nextFrame != null && nextFrame.readableBytes() > 0; + try { + if (fullStreamDecompressor != null) { + hasPartialMessage = hasPartialMessage || fullStreamDecompressor.hasPartialData(); + fullStreamDecompressor.close(); + } + if (unprocessed != null) { + unprocessed.close(); + } + if (nextFrame != null) { + nextFrame.close(); + } + } finally { + fullStreamDecompressor = null; + unprocessed = null; + nextFrame = null; + } + listener.deframerClosed(hasPartialMessage); + logger.debug("close complete"); + } + + /** + * Indicates whether or not this deframer has been closed. + */ + public boolean isClosed() { + return unprocessed == null && fullStreamDecompressor == null; + } + + /** Returns true if this deframer has already been closed or scheduled to close. */ + private boolean isClosedOrScheduledToClose() { + return isClosed() || closeWhenComplete; + } + + private boolean isStalled() { + if (fullStreamDecompressor != null) { + return fullStreamDecompressor.isStalled(); + } else { + return unprocessed.readableBytes() == 0; + } + } + + /** + * Reads and delivers as many messages to the listener as possible. + */ + private void deliver() { + // We can have reentrancy here when using a direct executor, triggered by calls to + // request more messages. This is safe as we simply loop until pendingDelivers = 0 + if (inDelivery) { + return; + } + inDelivery = true; + try { + // Process the uncompressed bytes. + while (!stopDelivery && pendingDeliveries > 0 && readRequiredBytes()) { + switch (state) { + case HEADER: + processHeader(); + break; + case BODY: + // Read the body and deliver the message. + processBody(); + + // Since we've delivered a message, decrement the number of pending + // deliveries remaining. + pendingDeliveries--; + break; + default: + throw new AssertionError("Invalid state: " + state); + } + } + + if (stopDelivery) { + close(); + return; + } + + /* + * We are stalled when there are no more bytes to process. This allows delivering errors as + * soon as the buffered input has been consumed, independent of whether the application + * has requested another message. At this point in the function, either all frames have been + * delivered, or unprocessed is empty. If there is a partial message, it will be inside next + * frame and not in unprocessed. If there is extra data but no pending deliveries, it will + * be in unprocessed. + */ + if (closeWhenComplete && isStalled()) { + close(); + } + } finally { + inDelivery = false; + } + } + + /** + * Attempts to read the required bytes into nextFrame. + * + * @return {@code true} if all of the required bytes have been read. + */ + private boolean readRequiredBytes() { + int totalBytesRead = 0; + int deflatedBytesRead = 0; + try { + if (nextFrame == null) { + nextFrame = new CompositeReadableBuffer(); + } + + // Read until the buffer contains all the required bytes. + int missingBytes; + while ((missingBytes = requiredLength - nextFrame.readableBytes()) > 0) { + if (fullStreamDecompressor != null) { + try { + if (inflatedBuffer == null || inflatedIndex == inflatedBuffer.length) { + inflatedBuffer = new byte[Math.min(missingBytes, MAX_BUFFER_SIZE)]; + inflatedIndex = 0; + } + int bytesToRead = Math.min(missingBytes, inflatedBuffer.length - inflatedIndex); + int n = fullStreamDecompressor.inflateBytes(inflatedBuffer, inflatedIndex, bytesToRead); + totalBytesRead += fullStreamDecompressor.getAndResetBytesConsumed(); + deflatedBytesRead += fullStreamDecompressor.getAndResetDeflatedBytesConsumed(); + if (n == 0) { + // No more inflated data is available. + return false; + } + nextFrame.addBuffer(ReadableBuffers.wrap(inflatedBuffer, inflatedIndex, n)); + inflatedIndex += n; + } catch (IOException e) { + throw new RuntimeException(e); + } catch (DataFormatException e) { + throw new RuntimeException(e); + } + } else { + if (unprocessed.readableBytes() == 0) { + // No more data is available. + return false; + } + int toRead = Math.min(missingBytes, unprocessed.readableBytes()); + totalBytesRead += toRead; + nextFrame.addBuffer(unprocessed.readBytes(toRead)); + } + } + return true; + } finally { + if (totalBytesRead > 0) { + listener.bytesRead(totalBytesRead); + if (state == State.BODY) { + if (fullStreamDecompressor != null) { + // With compressed streams, totalBytesRead can include gzip header and trailer metadata + statsTraceCtx.inboundWireSize(deflatedBytesRead); + inboundBodyWireSize += deflatedBytesRead; + } else { + statsTraceCtx.inboundWireSize(totalBytesRead); + inboundBodyWireSize += totalBytesRead; + } + } + } + } + } + + /** + * Processes the GRPC compression header which is composed of the compression flag and the outer + * frame length. + */ + private void processHeader() { + logger.debug("processHeader"); + int type = nextFrame.readUnsignedByte(); + if ((type & RESERVED_MASK) != 0) { + throw Status.INTERNAL.withDescription( + "gRPC frame header malformed: reserved bits not zero") + .asRuntimeException(); + } + compressedFlag = (type & COMPRESSED_FLAG_MASK) != 0; + + // Update the required length to include the length of the frame. + requiredLength = nextFrame.readInt(); + if (requiredLength < 0 || requiredLength > maxInboundMessageSize) { + throw Status.RESOURCE_EXHAUSTED.withDescription( + String.format(Locale.US, "gRPC message exceeds maximum size %d: %d", + maxInboundMessageSize, requiredLength)) + .asRuntimeException(); + } + + currentMessageSeqNo++; + statsTraceCtx.inboundMessage(currentMessageSeqNo); + transportTracer.reportMessageReceived(); + // Continue reading the frame body. + state = State.BODY; + logger.debug("processHeader complete, body length {}", requiredLength); + } + + /** + * Processes the GRPC message body, which depending on frame header flags may be compressed. + */ + private void processBody() { + logger.debug("processBody of length {}", requiredLength); + // There is no reliable way to get the uncompressed size per message when it's compressed, + // because the uncompressed bytes are provided through an InputStream whose total size is + // unknown until all bytes are read, and we don't know when it happens. + statsTraceCtx.inboundMessageRead(currentMessageSeqNo, inboundBodyWireSize, + (compressedFlag || fullStreamDecompressor != null) ? -1 : inboundBodyWireSize); + inboundBodyWireSize = 0; + InputStream stream = compressedFlag ? getCompressedBody() : getUncompressedBody(); + nextFrame.touch(); + nextFrame = null; + listener.messagesAvailable(new SingleMessageProducer(stream)); + + // Done with this frame, begin processing the next header. + state = State.HEADER; + requiredLength = HEADER_LENGTH; + logger.debug("processBody complete"); + } + + private InputStream getUncompressedBody() { + statsTraceCtx.inboundUncompressedSize(nextFrame.readableBytes()); + return ReadableBuffers.openStream(nextFrame, true); + } + + private InputStream getCompressedBody() { + if (decompressor == Codec.Identity.NONE) { + throw Status.INTERNAL.withDescription( + "Can't decode compressed gRPC message as compression not configured") + .asRuntimeException(); + } + + try { + // Enforce the maxMessageSize limit on the returned stream. + InputStream unlimitedStream = + decompressor.decompress(ReadableBuffers.openStream(nextFrame, true)); + return new SizeEnforcingInputStream( + unlimitedStream, maxInboundMessageSize, statsTraceCtx); + } catch (IOException e) { + throw new RuntimeException(e); + } + } + + /** + * An {@link InputStream} that enforces the {@link #maxMessageSize} limit for compressed frames. + */ + @VisibleForTesting + static final class SizeEnforcingInputStream extends FilterInputStream { + private final int maxMessageSize; + private final StatsTraceContext statsTraceCtx; + private long maxCount; + private long count; + private long mark = -1; + + SizeEnforcingInputStream(InputStream in, int maxMessageSize, StatsTraceContext statsTraceCtx) { + super(in); + this.maxMessageSize = maxMessageSize; + this.statsTraceCtx = statsTraceCtx; + } + + @Override + public int read() throws IOException { + int result = in.read(); + if (result != -1) { + count++; + } + verifySize(); + reportCount(); + return result; + } + + @Override + public int read(byte[] b, int off, int len) throws IOException { + int result = in.read(b, off, len); + if (result != -1) { + count += result; + } + verifySize(); + reportCount(); + return result; + } + + @Override + public long skip(long n) throws IOException { + long result = in.skip(n); + count += result; + verifySize(); + reportCount(); + return result; + } + + @Override + public synchronized void mark(int readlimit) { + in.mark(readlimit); + mark = count; + // it's okay to mark even if mark isn't supported, as reset won't work + } + + @Override + public synchronized void reset() throws IOException { + if (!in.markSupported()) { + throw new IOException("Mark not supported"); + } + if (mark == -1) { + throw new IOException("Mark not set"); + } + + in.reset(); + count = mark; + } + + private void reportCount() { + if (count > maxCount) { + statsTraceCtx.inboundUncompressedSize(count - maxCount); + maxCount = count; + } + } + + private void verifySize() { + if (count > maxMessageSize) { + throw Status.RESOURCE_EXHAUSTED + .withDescription("Decompressed gRPC message exceeds maximum size " + maxMessageSize) + .asRuntimeException(); + } + } + } + + private static class SingleMessageProducer implements StreamListener.MessageProducer { + private InputStream message; + + private SingleMessageProducer(InputStream message) { + this.message = message; + } + + @Nullable + @Override + public InputStream next() { + InputStream messageToReturn = message; + message = null; + return messageToReturn; + } + } +} diff --git a/framework/src/main/java/io/grpc/netty/NettyClientHandler.java b/framework/src/main/java/io/grpc/netty/NettyClientHandler.java new file mode 100644 index 00000000000..6a6b375034b --- /dev/null +++ b/framework/src/main/java/io/grpc/netty/NettyClientHandler.java @@ -0,0 +1,1172 @@ +/* + * Copyright 2014 The gRPC 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 io.grpc.netty; + +import static io.netty.handler.codec.http2.DefaultHttp2LocalFlowController.DEFAULT_WINDOW_UPDATE_RATIO; +import static io.netty.util.CharsetUtil.UTF_8; +import static io.netty.util.internal.ObjectUtil.checkNotNull; + +import com.google.common.annotations.VisibleForTesting; +import com.google.common.base.Preconditions; +import com.google.common.base.Stopwatch; +import com.google.common.base.Supplier; +import com.google.common.base.Ticker; +import io.grpc.Attributes; +import io.grpc.ChannelLogger; +import io.grpc.InternalChannelz; +import io.grpc.InternalStatus; +import io.grpc.Metadata; +import io.grpc.Status; +import io.grpc.StatusException; +import io.grpc.internal.ClientStreamListener.RpcProgress; +import io.grpc.internal.ClientTransport.PingCallback; +import io.grpc.internal.GrpcAttributes; +import io.grpc.internal.GrpcUtil; +import io.grpc.internal.Http2Ping; +import io.grpc.internal.InUseStateAggregator; +import io.grpc.internal.KeepAliveManager; +import io.grpc.internal.TransportTracer; +import io.grpc.netty.GrpcHttp2HeadersUtils.GrpcHttp2ClientHeadersDecoder; +import io.netty.buffer.ByteBuf; +import io.netty.buffer.ByteBufUtil; +import io.netty.buffer.Unpooled; +import io.netty.channel.Channel; +import io.netty.channel.ChannelFuture; +import io.netty.channel.ChannelFutureListener; +import io.netty.channel.ChannelHandlerContext; +import io.netty.channel.ChannelPromise; +import io.netty.handler.codec.http2.DecoratingHttp2FrameWriter; +import io.netty.handler.codec.http2.DefaultHttp2Connection; +import io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder; +import io.netty.handler.codec.http2.DefaultHttp2ConnectionEncoder; +import io.netty.handler.codec.http2.DefaultHttp2FrameReader; +import io.netty.handler.codec.http2.DefaultHttp2FrameWriter; +import io.netty.handler.codec.http2.DefaultHttp2HeadersEncoder; +import io.netty.handler.codec.http2.DefaultHttp2LocalFlowController; +import io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController; +import io.netty.handler.codec.http2.Http2CodecUtil; +import io.netty.handler.codec.http2.Http2Connection; +import io.netty.handler.codec.http2.Http2ConnectionAdapter; +import io.netty.handler.codec.http2.Http2ConnectionDecoder; +import io.netty.handler.codec.http2.Http2ConnectionEncoder; +import io.netty.handler.codec.http2.Http2Error; +import io.netty.handler.codec.http2.Http2Exception; +import io.netty.handler.codec.http2.Http2FrameAdapter; +import io.netty.handler.codec.http2.Http2FrameLogger; +import io.netty.handler.codec.http2.Http2FrameReader; +import io.netty.handler.codec.http2.Http2FrameWriter; +import io.netty.handler.codec.http2.Http2Headers; +import io.netty.handler.codec.http2.Http2HeadersDecoder; +import io.netty.handler.codec.http2.Http2HeadersEncoder; +import io.netty.handler.codec.http2.Http2InboundFrameLogger; +import io.netty.handler.codec.http2.Http2OutboundFrameLogger; +import io.netty.handler.codec.http2.Http2Settings; +import io.netty.handler.codec.http2.Http2Stream; +import io.netty.handler.codec.http2.Http2StreamVisitor; +import io.netty.handler.codec.http2.StreamBufferingEncoder; +import io.netty.handler.codec.http2.UniformStreamByteDistributor; +import io.netty.handler.logging.LogLevel; +import io.perfmark.PerfMark; +import io.perfmark.Tag; +import io.perfmark.TaskCloseable; +import java.nio.channels.ClosedChannelException; +import java.util.LinkedHashMap; +import java.util.Map; +import java.util.concurrent.Executor; +import javax.annotation.Nullable; +import lombok.extern.slf4j.Slf4j; + +/** + * Client-side Netty handler for GRPC processing. All event handlers are executed entirely within + * the context of the Netty Channel thread. + */ +@Slf4j +class NettyClientHandler extends AbstractNettyHandler { + static boolean enablePerRpcAuthorityCheck = + GrpcUtil.getFlag("GRPC_ENABLE_PER_RPC_AUTHORITY_CHECK", false); + + /** + * A message that simply passes through the channel without any real processing. It is useful to + * check if buffers have been drained and test the health of the channel in a single operation. + */ + static final Object NOOP_MESSAGE = new Object(); + + /** + * Status used when the transport has exhausted the number of streams. + */ + private static final Status EXHAUSTED_STREAMS_STATUS = + Status.UNAVAILABLE.withDescription("Stream IDs have been exhausted"); + private static final long USER_PING_PAYLOAD = 1111; + + private final Http2Connection.PropertyKey streamKey; + private final ClientTransportLifecycleManager lifecycleManager; + private final KeepAliveManager keepAliveManager; + // Returns new unstarted stopwatches + private final Supplier stopwatchFactory; + private final TransportTracer transportTracer; + private final Attributes eagAttributes; + private final String authority; + private final InUseStateAggregator inUseState = + new InUseStateAggregator() { + @Override + protected void handleInUse() { + lifecycleManager.notifyInUse(true); + } + + @Override + protected void handleNotInUse() { + lifecycleManager.notifyInUse(false); + } + }; + private final Map peerVerificationResults = + new LinkedHashMap() { + @Override + protected boolean removeEldestEntry(Map.Entry eldest) { + return size() > 100; + } + }; + + private WriteQueue clientWriteQueue; + private Http2Ping ping; + private Attributes attributes; + private InternalChannelz.Security securityInfo; + private Status abruptGoAwayStatus; + private Status channelInactiveReason; + + static NettyClientHandler newHandler( + ClientTransportLifecycleManager lifecycleManager, + @Nullable KeepAliveManager keepAliveManager, + boolean autoFlowControl, + int flowControlWindow, + int maxHeaderListSize, + int softLimitHeaderListSize, + Supplier stopwatchFactory, + Runnable tooManyPingsRunnable, + TransportTracer transportTracer, + Attributes eagAttributes, + String authority, + ChannelLogger negotiationLogger, + Ticker ticker) { + Preconditions.checkArgument(maxHeaderListSize > 0, "maxHeaderListSize must be positive"); + Http2HeadersDecoder headersDecoder = new GrpcHttp2ClientHeadersDecoder(maxHeaderListSize); + Http2FrameReader frameReader = new DefaultHttp2FrameReader(headersDecoder); + Http2HeadersEncoder encoder = new DefaultHttp2HeadersEncoder( + Http2HeadersEncoder.NEVER_SENSITIVE, false, 16, Integer.MAX_VALUE); + Http2FrameWriter frameWriter = new DefaultHttp2FrameWriter(encoder); + Http2Connection connection = new DefaultHttp2Connection(false); + UniformStreamByteDistributor dist = new UniformStreamByteDistributor(connection); + dist.minAllocationChunk(MIN_ALLOCATED_CHUNK); // Increased for benchmarks performance. + DefaultHttp2RemoteFlowController controller = + new DefaultHttp2RemoteFlowController(connection, dist); + connection.remote().flowController(controller); + + return newHandler( + connection, + frameReader, + frameWriter, + lifecycleManager, + keepAliveManager, + autoFlowControl, + flowControlWindow, + maxHeaderListSize, + softLimitHeaderListSize, + stopwatchFactory, + tooManyPingsRunnable, + transportTracer, + eagAttributes, + authority, + negotiationLogger, + ticker); + } + + @VisibleForTesting + static NettyClientHandler newHandler( + final Http2Connection connection, + Http2FrameReader frameReader, + Http2FrameWriter frameWriter, + ClientTransportLifecycleManager lifecycleManager, + KeepAliveManager keepAliveManager, + boolean autoFlowControl, + int flowControlWindow, + int maxHeaderListSize, + int softLimitHeaderListSize, + Supplier stopwatchFactory, + Runnable tooManyPingsRunnable, + TransportTracer transportTracer, + Attributes eagAttributes, + String authority, + ChannelLogger negotiationLogger, + Ticker ticker) { + Preconditions.checkNotNull(connection, "connection"); + Preconditions.checkNotNull(frameReader, "frameReader"); + Preconditions.checkNotNull(lifecycleManager, "lifecycleManager"); + Preconditions.checkArgument(flowControlWindow > 0, "flowControlWindow must be positive"); + Preconditions.checkArgument(maxHeaderListSize > 0, "maxHeaderListSize must be positive"); + Preconditions.checkArgument(softLimitHeaderListSize > 0, + "softLimitHeaderListSize must be positive"); + Preconditions.checkNotNull(stopwatchFactory, "stopwatchFactory"); + Preconditions.checkNotNull(tooManyPingsRunnable, "tooManyPingsRunnable"); + Preconditions.checkNotNull(eagAttributes, "eagAttributes"); + Preconditions.checkNotNull(authority, "authority"); + + Http2FrameLogger frameLogger = new Http2FrameLogger(LogLevel.DEBUG, NettyClientHandler.class); + frameReader = new Http2InboundFrameLogger(frameReader, frameLogger); + frameWriter = new Http2OutboundFrameLogger(frameWriter, frameLogger); + + PingCountingFrameWriter pingCounter; + frameWriter = pingCounter = new PingCountingFrameWriter(frameWriter); + + StreamBufferingEncoder encoder = + new StreamBufferingEncoder( + new DefaultHttp2ConnectionEncoder(connection, frameWriter)); + + // Create the local flow controller configured to auto-refill the connection window. + connection.local().flowController( + new DefaultHttp2LocalFlowController(connection, DEFAULT_WINDOW_UPDATE_RATIO, true)); + + Http2ConnectionDecoder decoder = new DefaultHttp2ConnectionDecoder(connection, encoder, + frameReader); + + transportTracer.setFlowControlWindowReader(new Utils.FlowControlReader(connection)); + + Http2Settings settings = new Http2Settings(); + settings.pushEnabled(false); + settings.initialWindowSize(flowControlWindow); + settings.maxConcurrentStreams(0); + settings.maxHeaderListSize(maxHeaderListSize); + + return new NettyClientHandler( + decoder, + encoder, + settings, + negotiationLogger, + lifecycleManager, + keepAliveManager, + stopwatchFactory, + tooManyPingsRunnable, + transportTracer, + eagAttributes, + authority, + autoFlowControl, + pingCounter, + ticker, + maxHeaderListSize, + softLimitHeaderListSize); + } + + private NettyClientHandler( + Http2ConnectionDecoder decoder, + Http2ConnectionEncoder encoder, + Http2Settings settings, + ChannelLogger negotiationLogger, + ClientTransportLifecycleManager lifecycleManager, + KeepAliveManager keepAliveManager, + Supplier stopwatchFactory, + final Runnable tooManyPingsRunnable, + TransportTracer transportTracer, + Attributes eagAttributes, + String authority, + boolean autoFlowControl, + PingLimiter pingLimiter, + Ticker ticker, + int maxHeaderListSize, + int softLimitHeaderListSize) { + super( + /* channelUnused= */ null, + decoder, + encoder, + settings, + negotiationLogger, + autoFlowControl, + pingLimiter, + ticker, + maxHeaderListSize, + softLimitHeaderListSize); + this.lifecycleManager = lifecycleManager; + this.keepAliveManager = keepAliveManager; + this.stopwatchFactory = stopwatchFactory; + this.transportTracer = Preconditions.checkNotNull(transportTracer); + this.eagAttributes = eagAttributes; + this.authority = authority; + this.attributes = Attributes.newBuilder() + .set(GrpcAttributes.ATTR_CLIENT_EAG_ATTRS, eagAttributes).build(); + + // Set the frame listener on the decoder. + decoder().frameListener(new FrameListener()); + + Http2Connection connection = encoder.connection(); + streamKey = connection.newKey(); + + connection.addListener(new Http2ConnectionAdapter() { + @Override + public void onGoAwayReceived(int lastStreamId, long errorCode, ByteBuf debugData) { + byte[] debugDataBytes = ByteBufUtil.getBytes(debugData); + goingAway(errorCode, debugDataBytes); + if (errorCode == Http2Error.ENHANCE_YOUR_CALM.code()) { + String data = new String(debugDataBytes, UTF_8); + logger.warn("Received GOAWAY with ENHANCE_YOUR_CALM. Debug data: {}", data); + if ("too_many_pings".equals(data)) { + tooManyPingsRunnable.run(); + } + } + } + + @Override + public void onStreamActive(Http2Stream stream) { + if (connection().numActiveStreams() == 1 + && NettyClientHandler.this.keepAliveManager != null) { + NettyClientHandler.this.keepAliveManager.onTransportActive(); + } + } + + @Override + public void onStreamClosed(Http2Stream stream) { + // Although streams with CALL_OPTIONS_RPC_OWNED_BY_BALANCER are not marked as "in-use" in + // the first place, we don't propagate that option here, and it's safe to reset the in-use + // state for them, which will be a cheap no-op. + inUseState.updateObjectInUse(stream, false); + if (connection().numActiveStreams() == 0 + && NettyClientHandler.this.keepAliveManager != null) { + NettyClientHandler.this.keepAliveManager.onTransportIdle(); + } + } + }); + } + + /** + * The protocol negotiation attributes, available once the protocol negotiation completes; + * otherwise returns {@code Attributes.EMPTY}. + */ + Attributes getAttributes() { + return attributes; + } + + /** + * Handler for commands sent from the stream. + */ + @Override + public void write(ChannelHandlerContext ctx, Object msg, ChannelPromise promise) + throws Exception { + if (msg instanceof CreateStreamCommand) { + createStream((CreateStreamCommand) msg, promise); + } else if (msg instanceof SendGrpcFrameCommand) { + sendGrpcFrame(ctx, (SendGrpcFrameCommand) msg, promise); + } else if (msg instanceof CancelClientStreamCommand) { + cancelStream(ctx, (CancelClientStreamCommand) msg, promise); + } else if (msg instanceof SendPingCommand) { + sendPingFrame(ctx, (SendPingCommand) msg, promise); + } else if (msg instanceof GracefulCloseCommand) { + gracefulClose(ctx, (GracefulCloseCommand) msg, promise); + } else if (msg instanceof ForcefulCloseCommand) { + forcefulClose(ctx, (ForcefulCloseCommand) msg, promise); + } else if (msg == NOOP_MESSAGE) { + ctx.write(Unpooled.EMPTY_BUFFER, promise); + } else { + throw new AssertionError("Write called for unexpected type: " + msg.getClass().getName()); + } + } + + void startWriteQueue(Channel channel) { + clientWriteQueue = new WriteQueue(channel); + } + + WriteQueue getWriteQueue() { + return clientWriteQueue; + } + + ClientTransportLifecycleManager getLifecycleManager() { + return lifecycleManager; + } + + /** + * Returns the given processed bytes back to inbound flow control. + */ + void returnProcessedBytes(Http2Stream stream, int bytes) { + try { + decoder().flowController().consumeBytes(stream, bytes); + } catch (Http2Exception e) { + throw new RuntimeException(e); + } + } + + private void onHeadersRead(int streamId, Http2Headers headers, boolean endStream) { + logger.debug("Received HEADERS frame for stream {}: endStream={}", streamId, endStream); + // Stream 1 is reserved for the Upgrade response, so we should ignore its headers here: + if (streamId != Http2CodecUtil.HTTP_UPGRADE_STREAM_ID) { + NettyClientStream.TransportState stream = clientStream(requireHttp2Stream(streamId)); + PerfMark.event("NettyClientHandler.onHeadersRead", stream.tag()); + logger.debug("Headers for stream {}: {}", streamId, headers); + // check metadata size vs soft limit + int h2HeadersSize = Utils.getH2HeadersSize(headers); + boolean shouldFail = + Utils.shouldRejectOnMetadataSizeSoftLimitExceeded( + h2HeadersSize, softLimitHeaderListSize, maxHeaderListSize); + if (shouldFail && endStream) { + stream.transportReportStatus(Status.RESOURCE_EXHAUSTED + .withDescription( + String.format( + "Server Status + Trailers of size %d exceeded Metadata size soft limit: %d", + h2HeadersSize, + softLimitHeaderListSize)), true, new Metadata()); + logger.debug("Rejected headers for stream {} due to size exceeding soft limit", streamId); + return; + } else if (shouldFail) { + stream.transportReportStatus(Status.RESOURCE_EXHAUSTED + .withDescription( + String.format( + "Server Headers of size %d exceeded Metadata size soft limit: %d", + h2HeadersSize, + softLimitHeaderListSize)), true, new Metadata()); + logger.debug("Rejected headers for stream {} due to size exceeding soft limit", streamId); + return; + } + stream.transportHeadersReceived(headers, endStream); + } + + if (keepAliveManager != null) { + keepAliveManager.onDataReceived(); + } + logger.debug("Completed processing of HEADERS frame for stream {}", streamId); + } + + /** + * Handler for an inbound HTTP/2 DATA frame. + */ + private void onDataRead(int streamId, ByteBuf data, int padding, boolean endOfStream) { + logger.debug("Received DATA frame for stream {} of length {} and padding {}", streamId, data.readableBytes(), padding); + flowControlPing().onDataRead(data.readableBytes(), padding); + NettyClientStream.TransportState stream = clientStream(requireHttp2Stream(streamId)); + PerfMark.event("NettyClientHandler.onDataRead", stream.tag()); + stream.transportDataReceived(data, endOfStream); + if (keepAliveManager != null) { + keepAliveManager.onDataReceived(); + } + logger.debug("Completed processing of DATA frame for stream {}", streamId); + } + + /** + * Handler for an inbound HTTP/2 RST_STREAM frame, terminating a stream. + */ + private void onRstStreamRead(int streamId, long errorCode) { + NettyClientStream.TransportState stream = clientStream(connection().stream(streamId)); + if (stream != null) { + PerfMark.event("NettyClientHandler.onRstStreamRead", stream.tag()); + Status status = statusFromH2Error(null, "RST_STREAM closed stream", errorCode, null); + stream.transportReportStatus( + status, + errorCode == Http2Error.REFUSED_STREAM.code() + ? RpcProgress.REFUSED : RpcProgress.PROCESSED, + false /*stop delivery*/, + new Metadata()); + if (keepAliveManager != null) { + keepAliveManager.onDataReceived(); + } + } + } + + @Override + public void close(ChannelHandlerContext ctx, ChannelPromise promise) throws Exception { + logger.debug("Network channel being closed by the application."); + if (ctx.channel().isActive()) { // Ignore notification that the socket was closed + lifecycleManager.notifyShutdown( + Status.UNAVAILABLE.withDescription("Transport closed for unknown reason")); + } + super.close(ctx, promise); + } + + /** + * Handler for the Channel shutting down. + */ + @Override + public void channelInactive(ChannelHandlerContext ctx) throws Exception { + try { + logger.debug("Network channel is closed"); + Status status = Status.UNAVAILABLE.withDescription("Network closed for unknown reason"); + lifecycleManager.notifyShutdown(status); + final Status streamStatus; + if (channelInactiveReason != null) { + streamStatus = channelInactiveReason; + } else { + streamStatus = lifecycleManager.getShutdownStatus(); + } + try { + cancelPing(lifecycleManager.getShutdownStatus()); + // Report status to the application layer for any open streams + connection().forEachActiveStream(new Http2StreamVisitor() { + @Override + public boolean visit(Http2Stream stream) throws Http2Exception { + NettyClientStream.TransportState clientStream = clientStream(stream); + if (clientStream != null) { + clientStream.transportReportStatus(streamStatus, false, new Metadata()); + } + return true; + } + }); + } finally { + lifecycleManager.notifyTerminated(status); + } + } finally { + // Close any open streams + super.channelInactive(ctx); + if (keepAliveManager != null) { + keepAliveManager.onTransportTermination(); + } + } + } + + @Override + public void handleProtocolNegotiationCompleted( + Attributes attributes, InternalChannelz.Security securityInfo) { + this.attributes = this.attributes.toBuilder().setAll(attributes).build(); + this.securityInfo = securityInfo; + super.handleProtocolNegotiationCompleted(attributes, securityInfo); + writeBufferingAndRemove(ctx().channel()); + } + + static void writeBufferingAndRemove(Channel channel) { + checkNotNull(channel, "channel"); + ChannelHandlerContext handlerCtx = + channel.pipeline().context(WriteBufferingAndExceptionHandler.class); + if (handlerCtx == null) { + return; + } + ((WriteBufferingAndExceptionHandler) handlerCtx.handler()).writeBufferedAndRemove(handlerCtx); + } + + @Override + public Attributes getEagAttributes() { + return eagAttributes; + } + + @Override + public String getAuthority() { + return authority; + } + + InternalChannelz.Security getSecurityInfo() { + return securityInfo; + } + + @Override + protected void onConnectionError(ChannelHandlerContext ctx, boolean outbound, Throwable cause, + Http2Exception http2Ex) { + logger.debug("Caught a connection error", cause); + lifecycleManager.notifyShutdown(Utils.statusFromThrowable(cause)); + // Parent class will shut down the Channel + super.onConnectionError(ctx, outbound, cause, http2Ex); + } + + @Override + protected void onStreamError(ChannelHandlerContext ctx, boolean outbound, Throwable cause, + Http2Exception.StreamException http2Ex) { + // Close the stream with a status that contains the cause. + NettyClientStream.TransportState stream = clientStream(connection().stream(http2Ex.streamId())); + if (stream != null) { + stream.transportReportStatus(Utils.statusFromThrowable(cause), false, new Metadata()); + } else { + logger.debug("Stream error for unknown stream {}", http2Ex.streamId(), cause); + } + + // Delegate to the base class to send a RST_STREAM. + super.onStreamError(ctx, outbound, cause, http2Ex); + } + + @Override + protected boolean isGracefulShutdownComplete() { + // Only allow graceful shutdown to complete after all pending streams have completed. + return super.isGracefulShutdownComplete() + && ((StreamBufferingEncoder) encoder()).numBufferedStreams() == 0; + } + + /** + * Attempts to create a new stream from the given command. If there are too many active streams, + * the creation request is queued. + */ + private void createStream(CreateStreamCommand command, ChannelPromise promise) + throws Exception { + if (lifecycleManager.getShutdownStatus() != null) { + command.stream().setNonExistent(); + // The connection is going away (it is really the GOAWAY case), + // just terminate the stream now. + command.stream().transportReportStatus( + lifecycleManager.getShutdownStatus(), RpcProgress.MISCARRIED, true, new Metadata()); + promise.setFailure(InternalStatus.asRuntimeExceptionWithoutStacktrace( + lifecycleManager.getShutdownStatus(), null)); + return; + } + + CharSequence authorityHeader = command.headers().authority(); + if (authorityHeader == null) { + Status authorityVerificationStatus = Status.UNAVAILABLE.withDescription( + "Missing authority header"); + command.stream().setNonExistent(); + command.stream().transportReportStatus( + Status.UNAVAILABLE, RpcProgress.PROCESSED, true, new Metadata()); + promise.setFailure(InternalStatus.asRuntimeExceptionWithoutStacktrace( + authorityVerificationStatus, null)); + return; + } + // No need to verify authority for the rpc outgoing header if it is same as the authority + // for the transport + if (!authority.contentEquals(authorityHeader)) { + Status authorityVerificationStatus = peerVerificationResults.get( + authorityHeader.toString()); + if (authorityVerificationStatus == null) { + if (attributes.get(GrpcAttributes.ATTR_AUTHORITY_VERIFIER) == null) { + authorityVerificationStatus = Status.UNAVAILABLE.withDescription( + "Authority verifier not found to verify authority"); + command.stream().setNonExistent(); + command.stream().transportReportStatus( + authorityVerificationStatus, RpcProgress.PROCESSED, true, new Metadata()); + promise.setFailure(InternalStatus.asRuntimeExceptionWithoutStacktrace( + authorityVerificationStatus, null)); + return; + } + authorityVerificationStatus = attributes.get(GrpcAttributes.ATTR_AUTHORITY_VERIFIER) + .verifyAuthority(authorityHeader.toString()); + peerVerificationResults.put(authorityHeader.toString(), authorityVerificationStatus); + if (!authorityVerificationStatus.isOk() && !enablePerRpcAuthorityCheck) { + logger.warn(String.format("%s.%s", + authorityVerificationStatus.getDescription(), + enablePerRpcAuthorityCheck + ? "" : " This will be an error in the future."), + InternalStatus.asRuntimeExceptionWithoutStacktrace( + authorityVerificationStatus, null)); + } + } + if (!authorityVerificationStatus.isOk()) { + if (enablePerRpcAuthorityCheck) { + command.stream().setNonExistent(); + command.stream().transportReportStatus( + authorityVerificationStatus, RpcProgress.PROCESSED, true, new Metadata()); + promise.setFailure(InternalStatus.asRuntimeExceptionWithoutStacktrace( + authorityVerificationStatus, null)); + return; + } + } + } + // Get the stream ID for the new stream. + int streamId; + try { + streamId = incrementAndGetNextStreamId(); + } catch (StatusException e) { + command.stream().setNonExistent(); + // Stream IDs have been exhausted for this connection. Fail the promise immediately. + promise.setFailure(e); + + // Initiate a graceful shutdown if we haven't already. + if (!connection().goAwaySent()) { + logger.debug("Stream IDs have been exhausted for this connection. " + + "Initiating graceful shutdown of the connection."); + lifecycleManager.notifyShutdown(e.getStatus()); + close(ctx(), ctx().newPromise()); + } + return; + } + if (connection().goAwayReceived()) { + Status s = abruptGoAwayStatus; + int maxActiveStreams = connection().local().maxActiveStreams(); + int lastStreamId = connection().local().lastStreamKnownByPeer(); + if (s == null) { + // Should be impossible, but handle pseudo-gracefully + s = Status.INTERNAL.withDescription( + "Failed due to abrupt GOAWAY, but can't find GOAWAY details"); + } else if (streamId > lastStreamId) { + s = s.augmentDescription( + "stream id: " + streamId + ", GOAWAY Last-Stream-ID:" + lastStreamId); + } else if (connection().local().numActiveStreams() == maxActiveStreams) { + s = s.augmentDescription("At MAX_CONCURRENT_STREAMS limit. limit: " + maxActiveStreams); + } + if (streamId > lastStreamId || connection().local().numActiveStreams() == maxActiveStreams) { + // This should only be reachable during onGoAwayReceived, as otherwise + // getShutdownThrowable() != null + command.stream().setNonExistent(); + command.stream().transportReportStatus(s, RpcProgress.MISCARRIED, true, new Metadata()); + promise.setFailure(s.asRuntimeException()); + return; + } + } + + NettyClientStream.TransportState stream = command.stream(); + Http2Headers headers = command.headers(); + stream.setId(streamId); + + try (TaskCloseable ignore = PerfMark.traceTask("NettyClientHandler.createStream")) { + PerfMark.linkIn(command.getLink()); + PerfMark.attachTag(stream.tag()); + createStreamTraced( + streamId, stream, headers, command.isGet(), command.shouldBeCountedForInUse(), promise); + } + } + + private void createStreamTraced( + final int streamId, + final NettyClientStream.TransportState stream, + final Http2Headers headers, + boolean isGet, + final boolean shouldBeCountedForInUse, + final ChannelPromise promise) { + // Create an intermediate promise so that we can intercept the failure reported back to the + // application. + ChannelPromise tempPromise = ctx().newPromise(); + encoder().writeHeaders(ctx(), streamId, headers, 0, isGet, tempPromise) + .addListener(new ChannelFutureListener() { + @Override + public void operationComplete(ChannelFuture future) throws Exception { + if (future.isSuccess()) { + // The http2Stream will be null in case a stream buffered in the encoder + // was canceled via RST_STREAM. + Http2Stream http2Stream = connection().stream(streamId); + if (http2Stream != null) { + stream.getStatsTraceContext().clientOutboundHeaders(); + http2Stream.setProperty(streamKey, stream); + + // This delays the in-use state until the I/O completes, which technically may + // be later than we would like. + if (shouldBeCountedForInUse) { + inUseState.updateObjectInUse(http2Stream, true); + } + + // Attach the client stream to the HTTP/2 stream object as user data. + stream.setHttp2Stream(http2Stream); + promise.setSuccess(); + } else { + // Otherwise, the stream has been cancelled and Netty is sending a + // RST_STREAM frame which causes it to purge pending writes from the + // flow-controller and delete the http2Stream. The stream listener has already + // been notified of cancellation so there is nothing to do. + // + // This process has been observed to fail in some circumstances, leaving listeners + // unanswered. Ensure that some exception has been delivered consistent with the + // implied RST_STREAM result above. + Status status = Status.INTERNAL.withDescription("unknown stream for connection"); + promise.setFailure(status.asRuntimeException()); + } + } else { + Throwable cause = future.cause(); + if (cause instanceof StreamBufferingEncoder.Http2GoAwayException) { + StreamBufferingEncoder.Http2GoAwayException e = + (StreamBufferingEncoder.Http2GoAwayException) cause; + Status status = statusFromH2Error( + Status.Code.UNAVAILABLE, "GOAWAY closed buffered stream", + e.errorCode(), e.debugData()); + cause = status.asRuntimeException(); + stream.transportReportStatus(status, RpcProgress.MISCARRIED, true, new Metadata()); + } else if (cause instanceof StreamBufferingEncoder.Http2ChannelClosedException) { + Status status = lifecycleManager.getShutdownStatus(); + if (status == null) { + status = Status.UNAVAILABLE.withCause(cause) + .withDescription("Connection closed while stream is buffered"); + } + stream.transportReportStatus(status, RpcProgress.MISCARRIED, true, new Metadata()); + } + promise.setFailure(cause); + } + } + }); + // When the HEADERS are not buffered because of MAX_CONCURRENT_STREAMS in + // StreamBufferingEncoder, the stream is created immediately even if the bytes of the HEADERS + // are delayed because the OS may have too much buffered and isn't accepting the write. The + // write promise is also delayed until flush(). However, we need to associate the netty stream + // with the transport state so that goingAway() and forcefulClose() and able to notify the + // stream of failures. + // + // This leaves a hole when MAX_CONCURRENT_STREAMS is reached, as http2Stream will be null, but + // it is better than nothing. + Http2Stream http2Stream = connection().stream(streamId); + if (http2Stream != null) { + http2Stream.setProperty(streamKey, stream); + } + } + + /** + * Cancels this stream. + */ + private void cancelStream(ChannelHandlerContext ctx, CancelClientStreamCommand cmd, + ChannelPromise promise) { + NettyClientStream.TransportState stream = cmd.stream(); + try (TaskCloseable ignore = PerfMark.traceTask("NettyClientHandler.cancelStream")) { + PerfMark.attachTag(stream.tag()); + PerfMark.linkIn(cmd.getLink()); + Status reason = cmd.reason(); + if (reason != null) { + stream.transportReportStatus(reason, true, new Metadata()); + } + if (!cmd.stream().isNonExistent()) { + encoder().writeRstStream(ctx, stream.id(), Http2Error.CANCEL.code(), promise); + } else { + promise.setSuccess(); + } + } + } + + /** + * Sends the given GRPC frame for the stream. + */ + private void sendGrpcFrame(ChannelHandlerContext ctx, SendGrpcFrameCommand cmd, + ChannelPromise promise) { + try (TaskCloseable ignore = PerfMark.traceTask("NettyClientHandler.sendGrpcFrame")) { + PerfMark.attachTag(cmd.stream().tag()); + PerfMark.linkIn(cmd.getLink()); + // Call the base class to write the HTTP/2 DATA frame. + // Note: no need to flush since this is handled by the outbound flow controller. + encoder().writeData(ctx, cmd.stream().id(), cmd.content(), 0, cmd.endStream(), promise); + } + } + + private void sendPingFrame(ChannelHandlerContext ctx, SendPingCommand msg, + ChannelPromise promise) { + try (TaskCloseable ignore = PerfMark.traceTask("NettyClientHandler.sendPingFrame")) { + PerfMark.linkIn(msg.getLink()); + sendPingFrameTraced(ctx, msg, promise); + } + } + + /** + * Sends a PING frame. If a ping operation is already outstanding, the callback in the message is + * registered to be called when the existing operation completes, and no new frame is sent. + */ + private void sendPingFrameTraced(ChannelHandlerContext ctx, SendPingCommand msg, + ChannelPromise promise) { + // Don't check lifecycleManager.getShutdownStatus() since we want to allow pings after shutdown + // but before termination. After termination, messages will no longer arrive because the + // pipeline clears all handlers on channel close. + + PingCallback callback = msg.callback(); + Executor executor = msg.executor(); + // we only allow one outstanding ping at a time, so just add the callback to + // any outstanding operation + if (ping != null) { + promise.setSuccess(); + ping.addCallback(callback, executor); + return; + } + + // Use a new promise to prevent calling the callback twice on write failure: here and in + // NettyClientTransport.ping(). It may appear strange, but it will behave the same as if + // ping != null above. + promise.setSuccess(); + promise = ctx().newPromise(); + // set outstanding operation + long data = USER_PING_PAYLOAD; + Stopwatch stopwatch = stopwatchFactory.get(); + stopwatch.start(); + ping = new Http2Ping(data, stopwatch); + ping.addCallback(callback, executor); + // and then write the ping + encoder().writePing(ctx, false, USER_PING_PAYLOAD, promise); + ctx.flush(); + final Http2Ping finalPing = ping; + promise.addListener(new ChannelFutureListener() { + @Override + public void operationComplete(ChannelFuture future) throws Exception { + if (future.isSuccess()) { + transportTracer.reportKeepAliveSent(); + return; + } + Throwable cause = future.cause(); + Status status = lifecycleManager.getShutdownStatus(); + if (cause instanceof ClosedChannelException) { + if (status == null) { + status = Status.UNKNOWN.withDescription("Ping failed but for unknown reason.") + .withCause(future.cause()); + } + } else { + status = Utils.statusFromThrowable(cause); + } + finalPing.failed(status); + if (ping == finalPing) { + ping = null; + } + } + }); + } + + private void gracefulClose(ChannelHandlerContext ctx, GracefulCloseCommand msg, + ChannelPromise promise) throws Exception { + lifecycleManager.notifyShutdown(msg.getStatus()); + // Explicitly flush to create any buffered streams before sending GOAWAY. + // TODO(ejona): determine if the need to flush is a bug in Netty + flush(ctx); + close(ctx, promise); + } + + private void forcefulClose(final ChannelHandlerContext ctx, final ForcefulCloseCommand msg, + ChannelPromise promise) throws Exception { + connection().forEachActiveStream(new Http2StreamVisitor() { + @Override + public boolean visit(Http2Stream stream) throws Http2Exception { + NettyClientStream.TransportState clientStream = clientStream(stream); + Tag tag = clientStream != null ? clientStream.tag() : PerfMark.createTag(); + try (TaskCloseable ignore = PerfMark.traceTask("NettyClientHandler.forcefulClose")) { + PerfMark.linkIn(msg.getLink()); + PerfMark.attachTag(tag); + if (clientStream != null) { + clientStream.transportReportStatus(msg.getStatus(), true, new Metadata()); + resetStream(ctx, stream.id(), Http2Error.CANCEL.code(), ctx.newPromise()); + } + stream.close(); + return true; + } + } + }); + close(ctx, promise); + } + + /** + * Handler for a GOAWAY being received. Fails any streams created after the + * last known stream. May only be called during a read. + */ + private void goingAway(long errorCode, byte[] debugData) { + Status finalStatus = statusFromH2Error( + Status.Code.UNAVAILABLE, "GOAWAY shut down transport", errorCode, debugData); + lifecycleManager.notifyGracefulShutdown(finalStatus); + abruptGoAwayStatus = statusFromH2Error( + Status.Code.UNAVAILABLE, "Abrupt GOAWAY closed unsent stream", errorCode, debugData); + // While this _should_ be UNAVAILABLE, Netty uses the wrong stream id in the GOAWAY when it + // fails streams due to HPACK failures (e.g., header list too large). To be more conservative, + // we assume any sent streams may be related to the GOAWAY. This should rarely impact users + // since the main time servers should use abrupt GOAWAYs is if there is a protocol error, and if + // there wasn't a protocol error the error code was probably NO_ERROR which is mapped to + // UNAVAILABLE. https://github.com/netty/netty/issues/10670 + final Status abruptGoAwayStatusConservative = statusFromH2Error( + null, "Abrupt GOAWAY closed sent stream", errorCode, debugData); + final boolean mayBeHittingNettyBug = errorCode != Http2Error.NO_ERROR.code(); + // Try to allocate as many in-flight streams as possible, to reduce race window of + // https://github.com/grpc/grpc-java/issues/2562 . To be of any help, the server has to + // gracefully shut down the connection with two GOAWAYs. gRPC servers generally send a PING + // after the first GOAWAY, so they can very precisely detect when the GOAWAY has been + // processed and thus this processing must be in-line before processing additional reads. + + // This can cause reentrancy, but should be minor since it is normal to handle writes in + // response to a read. Also, the call stack is rather shallow at this point + clientWriteQueue.drainNow(); + if (lifecycleManager.notifyShutdown(finalStatus)) { + // This is for the only RPCs that are actually covered by the GOAWAY error code. All other + // RPCs were not observed by the remote and so should be UNAVAILABLE. + channelInactiveReason = statusFromH2Error( + null, "Connection closed after GOAWAY", errorCode, debugData); + } + + final int lastKnownStream = connection().local().lastStreamKnownByPeer(); + try { + connection().forEachActiveStream(new Http2StreamVisitor() { + @Override + public boolean visit(Http2Stream stream) throws Http2Exception { + if (stream.id() > lastKnownStream) { + NettyClientStream.TransportState clientStream = clientStream(stream); + if (clientStream != null) { + // RpcProgress _should_ be REFUSED, but are being conservative. See comment for + // abruptGoAwayStatusConservative. This does reduce our ability to perform transparent + // retries, but only if something else caused a connection failure. + RpcProgress progress = mayBeHittingNettyBug + ? RpcProgress.PROCESSED + : RpcProgress.REFUSED; + clientStream.transportReportStatus( + abruptGoAwayStatusConservative, progress, false, new Metadata()); + } + stream.close(); + } + return true; + } + }); + } catch (Http2Exception e) { + throw new RuntimeException(e); + } + } + + private void cancelPing(Status s) { + if (ping != null) { + ping.failed(s); + ping = null; + } + } + + /** If {@code statusCode} is non-null, it will be used instead of the http2 error code mapping. */ + private Status statusFromH2Error( + Status.Code statusCode, String context, long errorCode, byte[] debugData) { + Status status = GrpcUtil.Http2Error.statusForCode(errorCode); + if (statusCode == null) { + statusCode = status.getCode(); + } + String debugString = ""; + if (debugData != null && debugData.length > 0) { + // If a debug message was provided, use it. + debugString = ", debug data: " + new String(debugData, UTF_8); + } + return statusCode.toStatus() + .withDescription(context + ". " + status.getDescription() + debugString); + } + + /** + * Gets the client stream associated to the given HTTP/2 stream object. + */ + private NettyClientStream.TransportState clientStream(Http2Stream stream) { + return stream == null ? null : (NettyClientStream.TransportState) stream.getProperty(streamKey); + } + + private int incrementAndGetNextStreamId() throws StatusException { + int nextStreamId = connection().local().incrementAndGetNextStreamId(); + if (nextStreamId < 0) { + logger.debug("Stream IDs have been exhausted for this connection. " + + "Initiating graceful shutdown of the connection."); + throw EXHAUSTED_STREAMS_STATUS.asException(); + } + return nextStreamId; + } + + private Http2Stream requireHttp2Stream(int streamId) { + Http2Stream stream = connection().stream(streamId); + if (stream == null) { + // This should never happen. + throw new AssertionError("Stream does not exist: " + streamId); + } + return stream; + } + + private class FrameListener extends Http2FrameAdapter { + private boolean firstSettings = true; + + @Override + public void onSettingsRead(ChannelHandlerContext ctx, Http2Settings settings) { + if (firstSettings) { + firstSettings = false; + attributes = lifecycleManager.filterAttributes(attributes); + lifecycleManager.notifyReady(); + } + } + + @Override + public int onDataRead(ChannelHandlerContext ctx, int streamId, ByteBuf data, int padding, + boolean endOfStream) throws Http2Exception { + logger.debug("onDataRead called for stream {} with length {} and padding {}", + streamId, data.readableBytes(), padding); + NettyClientHandler.this.onDataRead(streamId, data, padding, endOfStream); + logger.debug("onDataRead completed for stream {}, padding {}", streamId, padding); + return padding; + } + + @Override + public void onHeadersRead(ChannelHandlerContext ctx, + int streamId, + Http2Headers headers, + int streamDependency, + short weight, + boolean exclusive, + int padding, + boolean endStream) throws Http2Exception { + logger.debug("onHeadersRead called for stream {}", streamId); + NettyClientHandler.this.onHeadersRead(streamId, headers, endStream); + logger.debug("onHeadersRead completed for stream {}", streamId); + } + + @Override + public void onRstStreamRead(ChannelHandlerContext ctx, int streamId, long errorCode) + throws Http2Exception { + NettyClientHandler.this.onRstStreamRead(streamId, errorCode); + } + + @Override + public void onPingAckRead(ChannelHandlerContext ctx, long ackPayload) throws Http2Exception { + Http2Ping p = ping; + if (ackPayload == flowControlPing().payload()) { + flowControlPing().updateWindow(); + logger.debug("Window: {}", + decoder().flowController().initialWindowSize(connection().connectionStream())); + } else if (p != null) { + if (p.payload() == ackPayload) { + p.complete(); + ping = null; + } else { + logger.warn( + "Received unexpected ping ack. Expecting {}, got {}", p.payload(), ackPayload); + } + } else { + logger.warn("Received unexpected ping ack. No ping outstanding"); + } + if (keepAliveManager != null) { + keepAliveManager.onDataReceived(); + } + } + + @Override + public void onPingRead(ChannelHandlerContext ctx, long data) throws Http2Exception { + if (keepAliveManager != null) { + keepAliveManager.onDataReceived(); + } + } + } + + private static class PingCountingFrameWriter extends DecoratingHttp2FrameWriter + implements AbstractNettyHandler.PingLimiter { + private int pingCount; + + public PingCountingFrameWriter(Http2FrameWriter delegate) { + super(delegate); + } + + @Override + public boolean isPingAllowed() { + // "3 strikes" may cause the server to complain, so we limit ourselves to 2 or below. + return pingCount < 2; + } + + @Override + public ChannelFuture writeHeaders( + ChannelHandlerContext ctx, int streamId, Http2Headers headers, + int padding, boolean endStream, ChannelPromise promise) { + pingCount = 0; + return super.writeHeaders(ctx, streamId, headers, padding, endStream, promise); + } + + @Override + public ChannelFuture writeHeaders( + ChannelHandlerContext ctx, int streamId, Http2Headers headers, + int streamDependency, short weight, boolean exclusive, + int padding, boolean endStream, ChannelPromise promise) { + pingCount = 0; + return super.writeHeaders(ctx, streamId, headers, streamDependency, weight, exclusive, + padding, endStream, promise); + } + + @Override + public ChannelFuture writeWindowUpdate( + ChannelHandlerContext ctx, int streamId, int windowSizeIncrement, ChannelPromise promise) { + pingCount = 0; + return super.writeWindowUpdate(ctx, streamId, windowSizeIncrement, promise); + } + + @Override + public ChannelFuture writePing( + ChannelHandlerContext ctx, boolean ack, long data, ChannelPromise promise) { + if (!ack) { + pingCount++; + } + return super.writePing(ctx, ack, data, promise); + } + + @Override + public ChannelFuture writeData( + ChannelHandlerContext ctx, int streamId, ByteBuf data, int padding, boolean endStream, + ChannelPromise promise) { + if (data.isReadable()) { + pingCount = 0; + } + return super.writeData(ctx, streamId, data, padding, endStream, promise); + } + } +} diff --git a/framework/src/main/java/io/grpc/stub/ClientCalls.java b/framework/src/main/java/io/grpc/stub/ClientCalls.java new file mode 100644 index 00000000000..af1673e698c --- /dev/null +++ b/framework/src/main/java/io/grpc/stub/ClientCalls.java @@ -0,0 +1,1058 @@ +/* + * Copyright 2014 The gRPC 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 io.grpc.stub; + +import static com.google.common.base.Preconditions.checkNotNull; +import static com.google.common.base.Preconditions.checkState; + +import com.google.common.annotations.VisibleForTesting; +import com.google.common.base.MoreObjects; +import com.google.common.base.Preconditions; +import com.google.common.base.Predicate; +import com.google.common.base.Strings; +import com.google.common.util.concurrent.AbstractFuture; +import com.google.common.util.concurrent.ListenableFuture; +import io.grpc.CallOptions; +import io.grpc.Channel; +import io.grpc.ClientCall; +import io.grpc.ExperimentalApi; +import io.grpc.Metadata; +import io.grpc.MethodDescriptor; +import io.grpc.Status; +import io.grpc.StatusException; +import io.grpc.StatusRuntimeException; +import java.util.Iterator; +import java.util.NoSuchElementException; +import java.util.concurrent.ArrayBlockingQueue; +import java.util.concurrent.BlockingQueue; +import java.util.concurrent.ConcurrentLinkedQueue; +import java.util.concurrent.ExecutionException; +import java.util.concurrent.Executor; +import java.util.concurrent.Future; +import java.util.concurrent.RejectedExecutionException; +import java.util.concurrent.TimeoutException; +import java.util.concurrent.locks.Condition; +import java.util.concurrent.locks.Lock; +import java.util.concurrent.locks.LockSupport; +import java.util.concurrent.locks.ReentrantLock; +import javax.annotation.Nonnull; +import javax.annotation.Nullable; +import lombok.extern.slf4j.Slf4j; + +/** + * Utility functions for processing different call idioms. We have one-to-one correspondence + * between utilities in this class and the potential signatures in a generated stub class so + * that the runtime can vary behavior without requiring regeneration of the stub. + */ +@Slf4j +public final class ClientCalls { + + + @VisibleForTesting + static boolean rejectRunnableOnExecutor = + !Strings.isNullOrEmpty(System.getenv("GRPC_CLIENT_CALL_REJECT_RUNNABLE")) + && Boolean.parseBoolean(System.getenv("GRPC_CLIENT_CALL_REJECT_RUNNABLE")); + + // Prevent instantiation + private ClientCalls() {} + + /** + * Executes a unary call with a response {@link StreamObserver}. The {@code call} should not be + * already started. After calling this method, {@code call} should no longer be used. + * + *

If the provided {@code responseObserver} is an instance of {@link ClientResponseObserver}, + * {@code beforeStart()} will be called. + */ + public static void asyncUnaryCall( + ClientCall call, ReqT req, StreamObserver responseObserver) { + checkNotNull(responseObserver, "responseObserver"); + asyncUnaryRequestCall(call, req, responseObserver, false); + } + + /** + * Executes a server-streaming call with a response {@link StreamObserver}. The {@code call} + * should not be already started. After calling this method, {@code call} should no longer be + * used. + * + *

If the provided {@code responseObserver} is an instance of {@link ClientResponseObserver}, + * {@code beforeStart()} will be called. + */ + public static void asyncServerStreamingCall( + ClientCall call, ReqT req, StreamObserver responseObserver) { + checkNotNull(responseObserver, "responseObserver"); + asyncUnaryRequestCall(call, req, responseObserver, true); + } + + /** + * Executes a client-streaming call returning a {@link StreamObserver} for the request messages. + * The {@code call} should not be already started. After calling this method, {@code call} + * should no longer be used. + * + *

If the provided {@code responseObserver} is an instance of {@link ClientResponseObserver}, + * {@code beforeStart()} will be called. + * + * @return request stream observer. It will extend {@link ClientCallStreamObserver} + */ + public static StreamObserver asyncClientStreamingCall( + ClientCall call, + StreamObserver responseObserver) { + checkNotNull(responseObserver, "responseObserver"); + return asyncStreamingRequestCall(call, responseObserver, false); + } + + /** + * Executes a bidirectional-streaming call. The {@code call} should not be already started. + * After calling this method, {@code call} should no longer be used. + * + *

If the provided {@code responseObserver} is an instance of {@link ClientResponseObserver}, + * {@code beforeStart()} will be called. + * + * @return request stream observer. It will extend {@link ClientCallStreamObserver} + */ + public static StreamObserver asyncBidiStreamingCall( + ClientCall call, StreamObserver responseObserver) { + checkNotNull(responseObserver, "responseObserver"); + return asyncStreamingRequestCall(call, responseObserver, true); + } + + /** + * Executes a unary call and blocks on the response. The {@code call} should not be already + * started. After calling this method, {@code call} should no longer be used. + * + * @return the single response message. + * @throws StatusRuntimeException on error + */ + public static RespT blockingUnaryCall(ClientCall call, ReqT req) { + try { + return getUnchecked(futureUnaryCall(call, req)); + } catch (RuntimeException | Error e) { + throw cancelThrow(call, e); + } + } + + /** + * Executes a unary call and blocks on the response. The {@code call} should not be already + * started. After calling this method, {@code call} should no longer be used. + * + * @return the single response message. + * @throws StatusRuntimeException on error + */ + public static RespT blockingUnaryCall( + Channel channel, MethodDescriptor method, CallOptions callOptions, ReqT req) { + logger.debug("blockingUnaryCall: {}", method.getFullMethodName()); + ThreadlessExecutor executor = new ThreadlessExecutor(); + boolean interrupt = false; + ClientCall call = channel.newCall(method, + callOptions.withOption(ClientCalls.STUB_TYPE_OPTION, StubType.BLOCKING) + .withExecutor(executor)); + try { + ListenableFuture responseFuture = futureUnaryCall(call, req); + while (!responseFuture.isDone()) { + try { + executor.waitAndDrain(); + } catch (InterruptedException e) { + interrupt = true; + call.cancel("Thread interrupted", e); + // Now wait for onClose() to be called, so interceptors can clean up + } + } + executor.shutdown(); + return getUnchecked(responseFuture); + } catch (RuntimeException | Error e) { + // Something very bad happened. All bets are off; it may be dangerous to wait for onClose(). + throw cancelThrow(call, e); + } finally { + if (interrupt) { + Thread.currentThread().interrupt(); + } + } + } + + /** + * Executes a unary call and blocks on the response, + * throws a checked {@link StatusException}. + * + * @return the single response message. + * @throws StatusException on error + */ + public static RespT blockingV2UnaryCall( + Channel channel, MethodDescriptor method, CallOptions callOptions, ReqT req) + throws StatusException { + try { + return blockingUnaryCall(channel, method, callOptions, req); + } catch (StatusRuntimeException e) { + throw e.getStatus().asException(e.getTrailers()); + } + } + + /** + * Executes a server-streaming call returning a blocking {@link Iterator} over the + * response stream. The {@code call} should not be already started. After calling this method, + * {@code call} should no longer be used. + * + *

The returned iterator may throw {@link StatusRuntimeException} on error. + * + * @return an iterator over the response stream. + */ + public static Iterator blockingServerStreamingCall( + ClientCall call, ReqT req) { + BlockingResponseStream result = new BlockingResponseStream<>(call); + asyncUnaryRequestCall(call, req, result.listener()); + return result; + } + + /** + * Executes a server-streaming call returning a blocking {@link Iterator} over the + * response stream. + * + *

The returned iterator may throw {@link StatusRuntimeException} on error. + * + *

Warning: the iterator can result in leaks if not completely consumed. + * + * @return an iterator over the response stream. + */ + public static Iterator blockingServerStreamingCall( + Channel channel, MethodDescriptor method, CallOptions callOptions, ReqT req) { + ClientCall call = channel.newCall(method, + callOptions.withOption(ClientCalls.STUB_TYPE_OPTION, StubType.BLOCKING)); + + BlockingResponseStream result = new BlockingResponseStream<>(call); + asyncUnaryRequestCall(call, req, result.listener()); + return result; + } + + /** + * Initiates a client streaming call over the specified channel. It returns an + * object which can be used in a blocking manner to retrieve responses.. + * + *

The methods {@link BlockingClientCall#hasNext()} and {@link + * BlockingClientCall#cancel(String, Throwable)} can be used for more extensive control. + * + * @return A {@link BlockingClientCall} that has had the request sent and halfClose called + */ + @ExperimentalApi("https://github.com/grpc/grpc-java/issues/10918") + public static BlockingClientCall blockingV2ServerStreamingCall( + Channel channel, MethodDescriptor method, CallOptions callOptions, ReqT req) { + BlockingClientCall call = + blockingBidiStreamingCall(channel, method, callOptions); + + call.sendSingleRequest(req); + call.halfClose(); + return call; + } + + /** + * Initiates a server streaming call and sends the specified request to the server. It returns an + * object which can be used in a blocking manner to retrieve values from the server. After the + * last value has been read, the next read call will return null. + * + *

Call {@link BlockingClientCall#read()} for + * retrieving values. A {@code null} will be returned after the server has closed the stream. + * + *

The methods {@link BlockingClientCall#hasNext()} and {@link + * BlockingClientCall#cancel(String, Throwable)} can be used for more extensive control. + * + *


Example usage: + * 

 {@code  while ((response = call.read()) != null) { ... } }
+ * or + * 
 {@code
+   *   while (call.hasNext()) {
+   *     response = call.read();
+   *     ...
+   *   }
+   * }
+ * + *

Note that this paradigm is different from the original + * {@link #blockingServerStreamingCall(Channel, MethodDescriptor, CallOptions, Object)} + * which returns an iterator, which would leave the stream open if not completely consumed. + * + * @return A {@link BlockingClientCall} which can be used by the client to write and receive + * messages over the grpc channel. + */ + @ExperimentalApi("https://github.com/grpc/grpc-java/issues/10918") + public static BlockingClientCall blockingClientStreamingCall( + Channel channel, MethodDescriptor method, CallOptions callOptions) { + return blockingBidiStreamingCall(channel, method, callOptions); + } + + /** + * Initiate a bidirectional-streaming {@link ClientCall} and returning a stream object + * ({@link BlockingClientCall}) which can be used by the client to send and receive messages over + * the grpc channel. + * + * @return an object representing the call which can be used to read, write and terminate it. + */ + @ExperimentalApi("https://github.com/grpc/grpc-java/issues/10918") + public static BlockingClientCall blockingBidiStreamingCall( + Channel channel, MethodDescriptor method, CallOptions callOptions) { + ThreadSafeThreadlessExecutor executor = new ThreadSafeThreadlessExecutor(); + ClientCall call = channel.newCall(method, callOptions.withExecutor(executor)); + + BlockingClientCall blockingClientCall = new BlockingClientCall<>(call, executor); + + // Get the call started + call.start(blockingClientCall.getListener(), new Metadata()); + call.request(1); + + return blockingClientCall; + } + + /** + * Executes a unary call and returns a {@link ListenableFuture} to the response. The + * {@code call} should not be already started. After calling this method, {@code call} should no + * longer be used. + * + * @return a future for the single response message. + */ + public static ListenableFuture futureUnaryCall( + ClientCall call, ReqT req) { + GrpcFuture responseFuture = new GrpcFuture<>(call); + asyncUnaryRequestCall(call, req, new UnaryStreamToFuture<>(responseFuture)); + return responseFuture; + } + + /** + * Returns the result of calling {@link Future#get()} interruptibly on a task known not to throw a + * checked exception. + * + *

If interrupted, the interrupt is restored before throwing an exception.. + * + * @throws java.util.concurrent.CancellationException + * if {@code get} throws a {@code CancellationException}. + * @throws io.grpc.StatusRuntimeException if {@code get} throws an {@link ExecutionException} + * or an {@link InterruptedException}. + */ + private static V getUnchecked(Future future) { + try { + return future.get(); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + throw Status.CANCELLED + .withDescription("Thread interrupted") + .withCause(e) + .asRuntimeException(); + } catch (ExecutionException e) { + throw toStatusRuntimeException(e.getCause()); + } + } + + /** + * Wraps the given {@link Throwable} in a {@link StatusRuntimeException}. If it contains an + * embedded {@link StatusException} or {@link StatusRuntimeException}, the returned exception will + * contain the embedded trailers and status, with the given exception as the cause. Otherwise, an + * exception will be generated from an {@link Status#UNKNOWN} status. + */ + private static StatusRuntimeException toStatusRuntimeException(Throwable t) { + Throwable cause = checkNotNull(t, "t"); + while (cause != null) { + // If we have an embedded status, use it and replace the cause + if (cause instanceof StatusException) { + StatusException se = (StatusException) cause; + return new StatusRuntimeException(se.getStatus(), se.getTrailers()); + } else if (cause instanceof StatusRuntimeException) { + StatusRuntimeException se = (StatusRuntimeException) cause; + return new StatusRuntimeException(se.getStatus(), se.getTrailers()); + } + cause = cause.getCause(); + } + return Status.UNKNOWN.withDescription("unexpected exception").withCause(t) + .asRuntimeException(); + } + + /** + * Cancels a call, and throws the exception. + * + * @param t must be a RuntimeException or Error + */ + private static RuntimeException cancelThrow(ClientCall call, Throwable t) { + try { + call.cancel(null, t); + } catch (RuntimeException | Error e) { + logger.error("RuntimeException encountered while closing call", e); + } + if (t instanceof RuntimeException) { + throw (RuntimeException) t; + } else if (t instanceof Error) { + throw (Error) t; + } + // should be impossible + throw new AssertionError(t); + } + + private static void asyncUnaryRequestCall( + ClientCall call, ReqT req, StreamObserver responseObserver, + boolean streamingResponse) { + asyncUnaryRequestCall( + call, + req, + new StreamObserverToCallListenerAdapter<>( + responseObserver, + new CallToStreamObserverAdapter<>(call, streamingResponse))); + } + + private static void asyncUnaryRequestCall( + ClientCall call, + ReqT req, + StartableListener responseListener) { + startCall(call, responseListener); + try { + call.sendMessage(req); + call.halfClose(); + } catch (RuntimeException | Error e) { + throw cancelThrow(call, e); + } + } + + private static StreamObserver asyncStreamingRequestCall( + ClientCall call, + StreamObserver responseObserver, + boolean streamingResponse) { + CallToStreamObserverAdapter adapter = new CallToStreamObserverAdapter<>( + call, streamingResponse); + startCall( + call, + new StreamObserverToCallListenerAdapter<>(responseObserver, adapter)); + return adapter; + } + + private static void startCall( + ClientCall call, + StartableListener responseListener) { + logger.debug("ClientCalls.startCall"); + call.start(responseListener, new Metadata()); + responseListener.onStart(); + logger.debug("ClientCalls.startCall: call started"); + } + + private abstract static class StartableListener extends ClientCall.Listener { + abstract void onStart(); + } + + private static final class CallToStreamObserverAdapter + extends ClientCallStreamObserver { + private boolean frozen; + private final ClientCall call; + private final boolean streamingResponse; + private Runnable onReadyHandler; + private int initialRequest = 1; + private boolean autoRequestEnabled = true; + private boolean aborted = false; + private boolean completed = false; + + // Non private to avoid synthetic class + CallToStreamObserverAdapter(ClientCall call, boolean streamingResponse) { + this.call = call; + this.streamingResponse = streamingResponse; + } + + private void freeze() { + this.frozen = true; + } + + @Override + public void onNext(ReqT value) { + logger.debug("CallToStreamObserverAdapter.onNext"); + checkState(!aborted, "Stream was terminated by error, no further calls are allowed"); + checkState(!completed, "Stream is already completed, no further calls are allowed"); + call.sendMessage(value); + } + + @Override + public void onError(Throwable t) { + logger.debug("CallToStreamObserverAdapter.onError", t); + call.cancel("Cancelled by client with StreamObserver.onError()", t); + aborted = true; + } + + @Override + public void onCompleted() { + logger.debug("CallToStreamObserverAdapter.onCompleted"); + call.halfClose(); + completed = true; + } + + @Override + public boolean isReady() { + logger.debug("CallToStreamObserverAdapter.isReady"); + return call.isReady(); + } + + @Override + public void setOnReadyHandler(Runnable onReadyHandler) { + if (frozen) { + throw new IllegalStateException( + "Cannot alter onReadyHandler after call started. Use ClientResponseObserver"); + } + this.onReadyHandler = onReadyHandler; + logger.debug("CallToStreamObserverAdapter.setOnReadyHandler: handler set"); + } + + @Override + public void disableAutoInboundFlowControl() { + disableAutoRequestWithInitial(1); + } + + @Override + public void disableAutoRequestWithInitial(int request) { + if (frozen) { + throw new IllegalStateException( + "Cannot disable auto flow control after call started. Use ClientResponseObserver"); + } + Preconditions.checkArgument(request >= 0, "Initial requests must be non-negative"); + initialRequest = request; + autoRequestEnabled = false; + logger.debug("CallToStreamObserverAdapter.disableAutoRequestWithInitial: disabled with initial {}", request); + } + + @Override + public void request(int count) { + if (!streamingResponse && count == 1) { + // Initially ask for two responses from flow-control so that if a misbehaving server + // sends more than one response, we can catch it and fail it in the listener. + call.request(2); + } else { + call.request(count); + } + logger.debug("CallToStreamObserverAdapter.request: requested {}", count); + } + + @Override + public void setMessageCompression(boolean enable) { + call.setMessageCompression(enable); + logger.debug("CallToStreamObserverAdapter.setMessageCompression: {}", enable); + } + + @Override + public void cancel(@Nullable String message, @Nullable Throwable cause) { + call.cancel(message, cause); + logger.debug("CallToStreamObserverAdapter.cancel: call cancelled"); + } + } + + private static final class StreamObserverToCallListenerAdapter + extends StartableListener { + private final StreamObserver observer; + private final CallToStreamObserverAdapter adapter; + private boolean firstResponseReceived; + + // Non private to avoid synthetic class + StreamObserverToCallListenerAdapter( + StreamObserver observer, + CallToStreamObserverAdapter adapter) { + this.observer = observer; + this.adapter = adapter; + if (observer instanceof ClientResponseObserver) { + @SuppressWarnings("unchecked") + ClientResponseObserver clientResponseObserver = + (ClientResponseObserver) observer; + clientResponseObserver.beforeStart(adapter); + } + adapter.freeze(); + } + + @Override + public void onHeaders(Metadata headers) { + logger.debug("onHeaders: headers = {}", headers); + } + + @Override + public void onMessage(RespT message) { + logger.debug("onMessage: message = {}", message); + if (firstResponseReceived && !adapter.streamingResponse) { + throw Status.INTERNAL + .withDescription("More than one responses received for unary or client-streaming call") + .asRuntimeException(); + } + firstResponseReceived = true; + observer.onNext(message); + + if (adapter.streamingResponse && adapter.autoRequestEnabled) { + // Request delivery of the next inbound message. + adapter.request(1); + } + logger.debug("onMessage: observer notified"); + } + + @Override + public void onClose(Status status, Metadata trailers) { + logger.debug("onClose: status = {}", status); + if (status.isOk()) { + observer.onCompleted(); + } else { + observer.onError(status.asRuntimeException(trailers)); + } + logger.debug("onClose: observer notified"); + } + + @Override + public void onReady() { + logger.debug("onReady call"); + if (adapter.onReadyHandler != null) { + adapter.onReadyHandler.run(); + } + logger.debug("onReady: handler run"); + } + + @Override + void onStart() { + logger.debug("onStart call: requesting {}", adapter.initialRequest); + if (adapter.initialRequest > 0) { + adapter.request(adapter.initialRequest); + } + logger.debug("onStart: requested {}", adapter.initialRequest); + } + } + + /** + * Completes a {@link GrpcFuture} using {@link StreamObserver} events. + */ + private static final class UnaryStreamToFuture extends StartableListener { + private final GrpcFuture responseFuture; + private RespT value; + private boolean isValueReceived = false; + + // Non private to avoid synthetic class + UnaryStreamToFuture(GrpcFuture responseFuture) { + this.responseFuture = responseFuture; + } + + @Override + public void onHeaders(Metadata headers) { + logger.debug("onHeaders : headers = {}", headers); + } + + @Override + public void onMessage(RespT value) { + logger.debug("onMessage: value = {}", value); + if (this.isValueReceived) { + throw Status.INTERNAL.withDescription("More than one value received for unary call") + .asRuntimeException(); + } + this.value = value; + this.isValueReceived = true; + logger.debug("onMessage: value stored"); + } + + @Override + public void onClose(Status status, Metadata trailers) { + logger.debug("onClose: status: {}", status); + if (status.isOk()) { + if (!isValueReceived) { + // No value received so mark the future as an error + responseFuture.setException( + Status.INTERNAL.withDescription("No value received for unary call") + .asRuntimeException(trailers)); + } + responseFuture.set(value); + } else { + responseFuture.setException(status.asRuntimeException(trailers)); + } + logger.debug("onClose: future set"); + } + + @Override + void onStart() { + logger.debug("onStart: requesting 2"); + responseFuture.call.request(2); + logger.debug("onStart: requested 2"); + } + } + + private static final class GrpcFuture extends AbstractFuture { + private final ClientCall call; + + // Non private to avoid synthetic class + GrpcFuture(ClientCall call) { + this.call = call; + } + + @Override + protected void interruptTask() { + call.cancel("GrpcFuture was cancelled", null); + } + + @Override + protected boolean set(@Nullable RespT resp) { + return super.set(resp); + } + + @Override + protected boolean setException(Throwable throwable) { + return super.setException(throwable); + } + + @SuppressWarnings("MissingOverride") // Add @Override once Java 6 support is dropped + protected String pendingToString() { + return MoreObjects.toStringHelper(this).add("clientCall", call).toString(); + } + } + + /** + * Convert events on a {@link io.grpc.ClientCall.Listener} into a blocking {@link Iterator}. + * + *

The class is not thread-safe, but it does permit {@link ClientCall.Listener} calls in a + * separate thread from {@link Iterator} calls. + */ + // TODO(ejona86): determine how to allow ClientCall.cancel() in case of application error. + private static final class BlockingResponseStream implements Iterator { + // Due to flow control, only needs to hold up to 3 items: 2 for value, 1 for close. + // (2 for value, not 1, because of early request() in next()) + private final BlockingQueue buffer = new ArrayBlockingQueue<>(3); + private final StartableListener listener = new QueuingListener(); + private final ClientCall call; + // Only accessed when iterating. + private Object last; + + // Non private to avoid synthetic class + BlockingResponseStream(ClientCall call) { + this.call = call; + } + + StartableListener listener() { + return listener; + } + + private Object waitForNext() { + boolean interrupt = false; + try { + while (true) { + try { + return buffer.take(); + } catch (InterruptedException ie) { + interrupt = true; + call.cancel("Thread interrupted", ie); + // Now wait for onClose() to be called, to guarantee BlockingQueue doesn't fill + } + } + } finally { + if (interrupt) { + Thread.currentThread().interrupt(); + } + } + } + + @Override + public boolean hasNext() { + while (last == null) { + // Will block here indefinitely waiting for content. RPC timeouts defend against permanent + // hangs here as the call will become closed. + last = waitForNext(); + } + if (last instanceof StatusRuntimeException) { + // Rethrow the exception with a new stacktrace. + StatusRuntimeException e = (StatusRuntimeException) last; + throw e.getStatus().asRuntimeException(e.getTrailers()); + } + return last != this; + } + + @Override + public T next() { + // Eagerly call request(1) so it can be processing the next message while we wait for the + // current one, which reduces latency for the next message. With MigratingThreadDeframer and + // if the data has already been received, every other message can be delivered instantly. This + // can be run after hasNext(), but just would be slower. + if (!(last instanceof StatusRuntimeException) && last != this) { + call.request(1); + } + if (!hasNext()) { + throw new NoSuchElementException(); + } + @SuppressWarnings("unchecked") + T tmp = (T) last; + last = null; + return tmp; + } + + @Override + public void remove() { + throw new UnsupportedOperationException(); + } + + private final class QueuingListener extends StartableListener { + // Non private to avoid synthetic class + QueuingListener() {} + + private boolean done = false; + + @Override + public void onHeaders(Metadata headers) { + logger.debug("onHeaders: headers : {}", headers); + } + + @Override + public void onMessage(T value) { + logger.debug("onMessage: value : {}", value); + Preconditions.checkState(!done, "ClientCall already closed"); + buffer.add(value); + logger.debug("onMessage: added to buffer"); + } + + @Override + public void onClose(Status status, Metadata trailers) { + logger.debug("onClose: status : {}", status); + Preconditions.checkState(!done, "ClientCall already closed"); + if (status.isOk()) { + buffer.add(BlockingResponseStream.this); + } else { + buffer.add(status.asRuntimeException(trailers)); + } + done = true; + logger.debug("onClose: added to buffer"); + } + + @Override + void onStart() { + logger.debug("onStart: requesting 1"); + call.request(1); + logger.debug("onStart: requested 1"); + } + } + } + + @SuppressWarnings("serial") + @Slf4j + private static final class ThreadlessExecutor extends ConcurrentLinkedQueue + implements Executor { + private static final Object SHUTDOWN = new Object(); // sentinel + + // Set to the calling thread while it's parked, SHUTDOWN on RPC completion + private volatile Object waiter; + + // Non private to avoid synthetic class + ThreadlessExecutor() {} + + /** + * Waits until there is a Runnable, then executes it and all queued Runnables after it. + * Must only be called by one thread at a time. + */ + public void waitAndDrain() throws InterruptedException { + logger.debug("waitAndDrain: waiting to drain runnables"); + throwIfInterrupted(); + Runnable runnable = poll(); + if (runnable == null) { + waiter = Thread.currentThread(); + try { + while ((runnable = poll()) == null) { + LockSupport.park(this); + throwIfInterrupted(); + } + } finally { + waiter = null; + } + } + do { + runQuietly(runnable); + } while ((runnable = poll()) != null); + logger.debug("waitAndDrain: drained runnables"); + } + + private static void throwIfInterrupted() throws InterruptedException { + if (Thread.interrupted()) { + throw new InterruptedException(); + } + } + + /** + * Called after final call to {@link #waitAndDrain()}, from same thread. + */ + public void shutdown() { + logger.debug("shutdown: shutting down executor"); + waiter = SHUTDOWN; + Runnable runnable; + while ((runnable = poll()) != null) { + runQuietly(runnable); + } + logger.debug("shutdown: executor shut down"); + } + + private static void runQuietly(Runnable runnable) { + String name = runnable.getClass().getSimpleName(); + logger.debug("{} runQuietly: running runnable", name); + try { + runnable.run(); + } catch (Throwable t) { + logger.warn("Runnable threw exception", t); + } finally { + logger.debug("{} runQuietly: finished running runnable", name); + } + } + + @Override + public void execute(Runnable runnable) { + String name = runnable.getClass().getSimpleName(); + logger.debug("{} execute: adding runnable", name); + add(runnable); + Object waiter = this.waiter; + if (waiter != SHUTDOWN) { + LockSupport.unpark((Thread) waiter); // no-op if null + } else if (remove(runnable) && rejectRunnableOnExecutor) { + throw new RejectedExecutionException(); + } + logger.debug("{} execute: added runnable and signalled", name); + } + } + + @SuppressWarnings("serial") + @Slf4j + static final class ThreadSafeThreadlessExecutor extends ConcurrentLinkedQueue + implements Executor { + + private final Lock waiterLock = new ReentrantLock(); + private final Condition waiterCondition = waiterLock.newCondition(); + + // Non private to avoid synthetic class + ThreadSafeThreadlessExecutor() {} + + /** + * Waits until there is a Runnable, then executes it and all queued Runnables after it. + */ + public void waitAndDrain(Predicate predicate, T testTarget) throws InterruptedException { + try { + logger.debug("waitAndDrain: waiting to drain runnables"); + waitAndDrainWithTimeout(true, 0, predicate, testTarget); + logger.debug("waitAndDrain: woke up and drained"); + } catch (TimeoutException e) { + throw new AssertionError(e); // Should never happen + } + } + + /** + * Waits for up to specified nanoseconds until there is a Runnable, then executes it and all + * queued Runnables after it. + * + *

his should always be called in a loop that checks whether the reason we are waiting has + * been satisfied.

T + * + * @param waitForever ignore the rest of the arguments and wait until there is a task to run + * @param end System.nanoTime() to stop waiting if haven't been woken up yet + * @param predicate non-null condition to test for skipping wake or waking up threads + * @param testTarget object to pass to predicate + */ + public void waitAndDrainWithTimeout(boolean waitForever, long end, + @Nonnull Predicate predicate, T testTarget) + throws InterruptedException, TimeoutException { + logger.debug("waiting to drain runnables, long = {}", end); + throwIfInterrupted(); + Runnable runnable; + + while (!predicate.apply(testTarget)) { + waiterLock.lock(); + try { + while ((runnable = poll()) == null) { + if (predicate.apply(testTarget)) { + return; // The condition for which we were waiting is now satisfied + } + + if (waitForever) { + waiterCondition.await(); + } else { + long waitNanos = end - System.nanoTime(); + if (waitNanos <= 0) { + throw new TimeoutException(); // Deadline is expired + } + waiterCondition.awaitNanos(waitNanos); + } + } + } finally { + waiterLock.unlock(); + } + + do { + runQuietly(runnable); + } while ((runnable = poll()) != null); + // Wake everything up now that we've done something and they can check in their outer loop + // if they can continue or need to wait again. + signallAll(); + } + logger.debug("waitAndDrainWithTimeout: drained runnables"); + } + + /** + * Executes all queued Runnables and if there were any wakes up any waiting threads. + */ + public void drain() throws InterruptedException { + logger.debug("drain: draining runnables"); + throwIfInterrupted(); + Runnable runnable; + boolean didWork = false; + + while ((runnable = poll()) != null) { + runQuietly(runnable); + didWork = true; + } + + if (didWork) { + signallAll(); + } + logger.debug("drain: drained runnables"); + } + + private void signallAll() { + logger.debug("signallAll: signalling all waiters"); + waiterLock.lock(); + try { + waiterCondition.signalAll(); + } finally { + waiterLock.unlock(); + logger.debug("signallAll: signalled all waiters"); + } + } + + private static void runQuietly(Runnable runnable) { + String name = runnable.getClass().getSimpleName(); + logger.debug("{} runQuietly: running runnable", name); + try { + runnable.run(); + } catch (Throwable t) { + logger.warn("{} Runnable threw exception", name, t); + } finally { + logger.debug("{} runQuietly: finished running runnable", name); + } + } + + private static void throwIfInterrupted() throws InterruptedException { + if (Thread.interrupted()) { + throw new InterruptedException(); + } + } + + @Override + public void execute(Runnable runnable) { + String name = runnable.getClass().getSimpleName(); + logger.debug("{} execute: adding runnable", name); + waiterLock.lock(); + try { + add(runnable); + waiterCondition.signalAll(); // If anything is waiting let it wake up and process this task + } finally { + waiterLock.unlock(); + logger.debug("{} execute: added runnable and signalled", name); + } + } + } + + enum StubType { + BLOCKING, FUTURE, ASYNC + } + + /** + * Internal {@link CallOptions.Key} to indicate stub types. + */ + static final CallOptions.Key STUB_TYPE_OPTION = + CallOptions.Key.create("internal-stub-type"); +} diff --git a/framework/src/main/java/io/netty/handler/codec/http2/DefaultHttp2ConnectionDecoder.java b/framework/src/main/java/io/netty/handler/codec/http2/DefaultHttp2ConnectionDecoder.java new file mode 100644 index 00000000000..0c72d85e8f3 --- /dev/null +++ b/framework/src/main/java/io/netty/handler/codec/http2/DefaultHttp2ConnectionDecoder.java @@ -0,0 +1,878 @@ +/* + * Copyright 2014 The Netty Project + * + * The Netty Project 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: + * + * https://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 io.netty.handler.codec.http2; + +import static io.netty.handler.codec.http.HttpStatusClass.INFORMATIONAL; +import static io.netty.handler.codec.http2.Http2CodecUtil.DEFAULT_PRIORITY_WEIGHT; +import static io.netty.handler.codec.http2.Http2Error.INTERNAL_ERROR; +import static io.netty.handler.codec.http2.Http2Error.PROTOCOL_ERROR; +import static io.netty.handler.codec.http2.Http2Error.STREAM_CLOSED; +import static io.netty.handler.codec.http2.Http2Exception.connectionError; +import static io.netty.handler.codec.http2.Http2Exception.streamError; +import static io.netty.handler.codec.http2.Http2PromisedRequestVerifier.ALWAYS_VERIFY; +import static io.netty.handler.codec.http2.Http2Stream.State.CLOSED; +import static io.netty.handler.codec.http2.Http2Stream.State.HALF_CLOSED_REMOTE; +import static io.netty.util.internal.ObjectUtil.checkNotNull; +import static java.lang.Integer.MAX_VALUE; + +import io.netty.buffer.ByteBuf; +import io.netty.channel.ChannelHandlerContext; +import io.netty.handler.codec.http.HttpHeaderNames; +import io.netty.handler.codec.http.HttpStatusClass; +import io.netty.handler.codec.http.HttpUtil; +import io.netty.handler.codec.http2.Http2Connection.Endpoint; +import java.util.Iterator; +import java.util.List; +import java.util.Map.Entry; +import lombok.extern.slf4j.Slf4j; + +/** + * Provides the default implementation for processing inbound frame events and delegates to a + * {@link Http2FrameListener} + *

+ * This class will read HTTP/2 frames and delegate the events to a {@link Http2FrameListener} + *

+ * This interface enforces inbound flow control functionality through + * {@link Http2LocalFlowController} + */ +@Slf4j +public class DefaultHttp2ConnectionDecoder implements Http2ConnectionDecoder { + private final Http2Connection connection; + private final Http2ConnectionEncoder encoder; + private final Http2FrameReader frameReader; + private final Http2PromisedRequestVerifier requestVerifier; + private final Http2SettingsReceivedConsumer settingsReceivedConsumer; + private final boolean autoAckPing; + private final Http2Connection.PropertyKey contentLengthKey; + private final boolean validateHeaders; + private Http2FrameListener internalFrameListener = new PrefaceFrameListener(); + private Http2LifecycleManager lifecycleManager; + private Http2FrameListener listener; + + public DefaultHttp2ConnectionDecoder(Http2Connection connection, + Http2ConnectionEncoder encoder, + Http2FrameReader frameReader) { + this(connection, encoder, frameReader, ALWAYS_VERIFY); + } + + public DefaultHttp2ConnectionDecoder(Http2Connection connection, + Http2ConnectionEncoder encoder, + Http2FrameReader frameReader, + Http2PromisedRequestVerifier requestVerifier) { + this(connection, encoder, frameReader, requestVerifier, true); + } + + /** + * Create a new instance. + * + * @param connection The {@link Http2Connection} associated with this decoder. + * @param encoder The {@link Http2ConnectionEncoder} associated with this decoder. + * @param frameReader Responsible for reading/parsing the raw frames. As opposed to this object which applies + * h2 semantics on top of the frames. + * @param requestVerifier Determines if push promised streams are valid. + * @param autoAckSettings {@code false} to disable automatically applying and sending settings acknowledge frame. + * The {@code Http2ConnectionEncoder} is expected to be an instance of {@link Http2SettingsReceivedConsumer} and + * will apply the earliest received but not yet ACKed SETTINGS when writing the SETTINGS ACKs. + * {@code true} to enable automatically applying and sending settings acknowledge frame. + */ + public DefaultHttp2ConnectionDecoder(Http2Connection connection, + Http2ConnectionEncoder encoder, + Http2FrameReader frameReader, + Http2PromisedRequestVerifier requestVerifier, + boolean autoAckSettings) { + this(connection, encoder, frameReader, requestVerifier, autoAckSettings, true); + } + + @Deprecated + public DefaultHttp2ConnectionDecoder(Http2Connection connection, + Http2ConnectionEncoder encoder, + Http2FrameReader frameReader, + Http2PromisedRequestVerifier requestVerifier, + boolean autoAckSettings, + boolean autoAckPing) { + this(connection, encoder, frameReader, requestVerifier, autoAckSettings, autoAckPing, true); + } + + /** + * Create a new instance. + * + * @param connection The {@link Http2Connection} associated with this decoder. + * @param encoder The {@link Http2ConnectionEncoder} associated with this decoder. + * @param frameReader Responsible for reading/parsing the raw frames. As opposed to this object which applies + * h2 semantics on top of the frames. + * @param requestVerifier Determines if push promised streams are valid. + * @param autoAckSettings {@code false} to disable automatically applying and sending settings acknowledge frame. + * The {@code Http2ConnectionEncoder} is expected to be an instance of + * {@link Http2SettingsReceivedConsumer} and will apply the earliest received but not yet + * ACKed SETTINGS when writing the SETTINGS ACKs. {@code true} to enable automatically + * applying and sending settings acknowledge frame. + * @param autoAckPing {@code false} to disable automatically sending ping acknowledge frame. {@code true} to enable + * automatically sending ping ack frame. + */ + public DefaultHttp2ConnectionDecoder(Http2Connection connection, + Http2ConnectionEncoder encoder, + Http2FrameReader frameReader, + Http2PromisedRequestVerifier requestVerifier, + boolean autoAckSettings, + boolean autoAckPing, + boolean validateHeaders) { + this.validateHeaders = validateHeaders; + this.autoAckPing = autoAckPing; + if (autoAckSettings) { + settingsReceivedConsumer = null; + } else { + if (!(encoder instanceof Http2SettingsReceivedConsumer)) { + throw new IllegalArgumentException("disabling autoAckSettings requires the encoder to be a " + + Http2SettingsReceivedConsumer.class); + } + settingsReceivedConsumer = (Http2SettingsReceivedConsumer) encoder; + } + this.connection = checkNotNull(connection, "connection"); + contentLengthKey = this.connection.newKey(); + this.frameReader = checkNotNull(frameReader, "frameReader"); + this.encoder = checkNotNull(encoder, "encoder"); + this.requestVerifier = checkNotNull(requestVerifier, "requestVerifier"); + if (connection.local().flowController() == null) { + connection.local().flowController(new DefaultHttp2LocalFlowController(connection)); + } + connection.local().flowController().frameWriter(encoder.frameWriter()); + } + + @Override + public void lifecycleManager(Http2LifecycleManager lifecycleManager) { + this.lifecycleManager = checkNotNull(lifecycleManager, "lifecycleManager"); + } + + @Override + public Http2Connection connection() { + return connection; + } + + @Override + public final Http2LocalFlowController flowController() { + return connection.local().flowController(); + } + + @Override + public void frameListener(Http2FrameListener listener) { + this.listener = checkNotNull(listener, "listener"); + } + + @Override + public Http2FrameListener frameListener() { + return listener; + } + + @Override + public boolean prefaceReceived() { + return FrameReadListener.class == internalFrameListener.getClass(); + } + + @Override + public void decodeFrame(ChannelHandlerContext ctx, ByteBuf in, List out) throws Http2Exception { + frameReader.readFrame(ctx, in, internalFrameListener); + } + + @Override + public Http2Settings localSettings() { + Http2Settings settings = new Http2Settings(); + Http2FrameReader.Configuration config = frameReader.configuration(); + Http2HeadersDecoder.Configuration headersConfig = config.headersConfiguration(); + Http2FrameSizePolicy frameSizePolicy = config.frameSizePolicy(); + settings.initialWindowSize(flowController().initialWindowSize()); + settings.maxConcurrentStreams(connection.remote().maxActiveStreams()); + settings.headerTableSize(headersConfig.maxHeaderTableSize()); + settings.maxFrameSize(frameSizePolicy.maxFrameSize()); + settings.maxHeaderListSize(headersConfig.maxHeaderListSize()); + if (!connection.isServer()) { + // Only set the pushEnabled flag if this is a client endpoint. + settings.pushEnabled(connection.local().allowPushTo()); + } + return settings; + } + + @Override + public void close() { + frameReader.close(); + } + + /** + * Calculate the threshold in bytes which should trigger a {@code GO_AWAY} if a set of headers exceeds this amount. + * + * @param maxHeaderListSize SETTINGS_MAX_HEADER_LIST_SIZE for the local + * endpoint. + * @return the threshold in bytes which should trigger a {@code GO_AWAY} if a set of headers exceeds this amount. + */ + protected long calculateMaxHeaderListSizeGoAway(long maxHeaderListSize) { + return Http2CodecUtil.calculateMaxHeaderListSizeGoAway(maxHeaderListSize); + } + + private int unconsumedBytes(Http2Stream stream) { + return flowController().unconsumedBytes(stream); + } + + void onGoAwayRead0(ChannelHandlerContext ctx, int lastStreamId, long errorCode, ByteBuf debugData) + throws Http2Exception { + listener.onGoAwayRead(ctx, lastStreamId, errorCode, debugData); + connection.goAwayReceived(lastStreamId, errorCode, debugData); + } + + void onUnknownFrame0(ChannelHandlerContext ctx, byte frameType, int streamId, Http2Flags flags, + ByteBuf payload) throws Http2Exception { + listener.onUnknownFrame(ctx, frameType, streamId, flags, payload); + } + + // See https://tools.ietf.org/html/rfc7540#section-8.1.2.6 + private void verifyContentLength(Http2Stream stream, int data, boolean isEnd) throws Http2Exception { + ContentLength contentLength = stream.getProperty(contentLengthKey); + if (contentLength != null) { + try { + contentLength.increaseReceivedBytes(connection.isServer(), stream.id(), data, isEnd); + } finally { + if (isEnd) { + stream.removeProperty(contentLengthKey); + } + } + } + } + + private static final class ContentLength { + private final long expected; + private long seen; + + ContentLength(long expected) { + this.expected = expected; + } + + void increaseReceivedBytes(boolean server, int streamId, int bytes, boolean isEnd) throws Http2Exception { + seen += bytes; + // Check for overflow + if (seen < 0) { + throw streamError(streamId, PROTOCOL_ERROR, + "Received amount of data did overflow and so not match content-length header %d", expected); + } + // Check if we received more data then what was advertised via the content-length header. + if (seen > expected) { + throw streamError(streamId, PROTOCOL_ERROR, + "Received amount of data %d does not match content-length header %d", seen, expected); + } + + if (isEnd) { + if (seen == 0 && !server) { + // This may be a response to a HEAD request, let's just allow it. + return; + } + + // Check that we really saw what was told via the content-length header. + if (expected > seen) { + throw streamError(streamId, PROTOCOL_ERROR, + "Received amount of data %d does not match content-length header %d", seen, expected); + } + } + } + } + + /** + * Handles all inbound frames from the network. + */ + private final class FrameReadListener implements Http2FrameListener { + @Override + public int onDataRead(final ChannelHandlerContext ctx, int streamId, ByteBuf data, int padding, + boolean endOfStream) throws Http2Exception { + logger.debug("onDataRead streamId: {}, data readableBytes: {}, padding: {}, endOfStream: {}", + streamId, data.readableBytes(), padding, endOfStream); + Http2Stream stream = connection.stream(streamId); + Http2LocalFlowController flowController = flowController(); + int readable = data.readableBytes(); + int bytesToReturn = readable + padding; + + final boolean shouldIgnore; + try { + shouldIgnore = shouldIgnoreHeadersOrDataFrame(ctx, streamId, stream, endOfStream, "DATA"); + } catch (Http2Exception e) { + // Ignoring this frame. We still need to count the frame towards the connection flow control + // window, but we immediately mark all bytes as consumed. + flowController.receiveFlowControlledFrame(stream, data, padding, endOfStream); + flowController.consumeBytes(stream, bytesToReturn); + logger.debug("onDataRead ignoring data frame due to exception: {}", e.getMessage()); + throw e; + } catch (Throwable t) { + logger.error("onDataRead unexpected error: ", t); + throw connectionError(INTERNAL_ERROR, t, "Unhandled error on data stream id %d", streamId); + } + + if (shouldIgnore) { + // Ignoring this frame. We still need to count the frame towards the connection flow control + // window, but we immediately mark all bytes as consumed. + flowController.receiveFlowControlledFrame(stream, data, padding, endOfStream); + flowController.consumeBytes(stream, bytesToReturn); + + // Verify that the stream may have existed after we apply flow control. + verifyStreamMayHaveExisted(streamId, endOfStream, "DATA"); + logger.debug("onDataRead ignoring data frame for stream id {}", streamId); + // All bytes have been consumed. + return bytesToReturn; + } + Http2Exception error = null; + switch (stream.state()) { + case OPEN: + case HALF_CLOSED_LOCAL: + break; + case HALF_CLOSED_REMOTE: + case CLOSED: + error = streamError(stream.id(), STREAM_CLOSED, "Stream %d in unexpected state: %s", + stream.id(), stream.state()); + break; + default: + error = streamError(stream.id(), PROTOCOL_ERROR, + "Stream %d in unexpected state: %s", stream.id(), stream.state()); + break; + } + + int unconsumedBytes = unconsumedBytes(stream); + try { + flowController.receiveFlowControlledFrame(stream, data, padding, endOfStream); + // Update the unconsumed bytes after flow control is applied. + unconsumedBytes = unconsumedBytes(stream); + + // If the stream is in an invalid state to receive the frame, throw the error. + if (error != null) { + logger.debug("onDataRead throwing error for stream id {}: {}", streamId, error.getMessage()); + throw error; + } + + verifyContentLength(stream, readable, endOfStream); + + // Call back the application and retrieve the number of bytes that have been + // immediately processed. + bytesToReturn = listener.onDataRead(ctx, streamId, data, padding, endOfStream); + + if (endOfStream) { + logger.debug("onDataRead endOfStream for stream id {}", streamId); + lifecycleManager.closeStreamRemote(stream, ctx.newSucceededFuture()); + } + logger.debug("onDataRead processed {} bytes for stream id {}", bytesToReturn, streamId); + return bytesToReturn; + } catch (Http2Exception e) { + // If an exception happened during delivery, the listener may have returned part + // of the bytes before the error occurred. If that's the case, subtract that from + // the total processed bytes so that we don't return too many bytes. + int delta = unconsumedBytes - unconsumedBytes(stream); + bytesToReturn -= delta; + logger.debug("onDataRead throwing Http2Exception for stream id {}: {}", streamId, e.getMessage()); + throw e; + } catch (RuntimeException e) { + // If an exception happened during delivery, the listener may have returned part + // of the bytes before the error occurred. If that's the case, subtract that from + // the total processed bytes so that we don't return too many bytes. + int delta = unconsumedBytes - unconsumedBytes(stream); + bytesToReturn -= delta; + logger.debug("onDataRead throwing RuntimeException for stream id {}: {}", streamId, e.getMessage()); + throw e; + } finally { + // If appropriate, return the processed bytes to the flow controller. + flowController.consumeBytes(stream, bytesToReturn); + logger.debug("onDataRead consumed {} bytes for stream id {}", bytesToReturn, streamId); + } + } + + @Override + public void onHeadersRead(ChannelHandlerContext ctx, int streamId, Http2Headers headers, int padding, + boolean endOfStream) throws Http2Exception { + onHeadersRead(ctx, streamId, headers, 0, DEFAULT_PRIORITY_WEIGHT, false, padding, endOfStream); + } + + @Override + public void onHeadersRead(ChannelHandlerContext ctx, int streamId, Http2Headers headers, int streamDependency, + short weight, boolean exclusive, int padding, boolean endOfStream) throws Http2Exception { + logger.debug("onHeadersRead streamId: {}, streamDependency: {}, weight: {}, exclusive: {}, " + + "padding: {}, endOfStream: {}, headers: {}", + streamId, streamDependency, weight, exclusive, padding, endOfStream, headers); + Http2Stream stream = connection.stream(streamId); + boolean allowHalfClosedRemote = false; + boolean isTrailers = false; + if (stream == null && !connection.streamMayHaveExisted(streamId)) { + stream = connection.remote().createStream(streamId, endOfStream); + // Allow the state to be HALF_CLOSE_REMOTE if we're creating it in that state. + allowHalfClosedRemote = stream.state() == HALF_CLOSED_REMOTE; + } else if (stream != null) { + isTrailers = stream.isHeadersReceived(); + } + + if (shouldIgnoreHeadersOrDataFrame(ctx, streamId, stream, endOfStream, "HEADERS")) { + logger.debug("onHeadersRead ignoring headers frame for stream id {}", streamId); + return; + } + + boolean isInformational = !connection.isServer() && + HttpStatusClass.valueOf(headers.status()) == INFORMATIONAL; + if ((isInformational || !endOfStream) && stream.isHeadersReceived() || stream.isTrailersReceived()) { + throw streamError(streamId, PROTOCOL_ERROR, + "Stream %d received too many headers EOS: %s state: %s", + streamId, endOfStream, stream.state()); + } + + switch (stream.state()) { + case RESERVED_REMOTE: + stream.open(endOfStream); + break; + case OPEN: + case HALF_CLOSED_LOCAL: + // Allowed to receive headers in these states. + break; + case HALF_CLOSED_REMOTE: + if (!allowHalfClosedRemote) { + throw streamError(stream.id(), STREAM_CLOSED, "Stream %d in unexpected state: %s", + stream.id(), stream.state()); + } + break; + case CLOSED: + throw streamError(stream.id(), STREAM_CLOSED, "Stream %d in unexpected state: %s", + stream.id(), stream.state()); + default: + // Connection error. + throw connectionError(PROTOCOL_ERROR, "Stream %d in unexpected state: %s", stream.id(), + stream.state()); + } + + if (!isTrailers) { + // extract the content-length header + List contentLength = headers.getAll(HttpHeaderNames.CONTENT_LENGTH); + if (contentLength != null && !contentLength.isEmpty()) { + try { + long cLength = HttpUtil.normalizeAndGetContentLength(contentLength, false, true); + if (cLength != -1) { + headers.setLong(HttpHeaderNames.CONTENT_LENGTH, cLength); + stream.setProperty(contentLengthKey, new ContentLength(cLength)); + } + } catch (IllegalArgumentException e) { + throw streamError(stream.id(), PROTOCOL_ERROR, e, + "Multiple content-length headers received"); + } + } + // Use size() instead of isEmpty() for backward compatibility with grpc-java prior to 1.59.1, + // see https://github.com/grpc/grpc-java/issues/10665 + } else if (validateHeaders && headers.size() > 0) { + // Need to check trailers don't contain pseudo headers. According to RFC 9113 + // Trailers MUST NOT include pseudo-header fields (Section 8.3). + for (Iterator> iterator = + headers.iterator(); iterator.hasNext(); ) { + CharSequence name = iterator.next().getKey(); + if (Http2Headers.PseudoHeaderName.hasPseudoHeaderFormat(name)) { + throw streamError(stream.id(), PROTOCOL_ERROR, + "Found invalid Pseudo-Header in trailers: %s", name); + } + } + } + + stream.headersReceived(isInformational); + verifyContentLength(stream, 0, endOfStream); + encoder.flowController().updateDependencyTree(streamId, streamDependency, weight, exclusive); + listener.onHeadersRead(ctx, streamId, headers, streamDependency, + weight, exclusive, padding, endOfStream); + logger.debug("onHeadersRead delivered headers for stream id {}", streamId); + // If the headers completes this stream, close it. + if (endOfStream) { + logger.debug("onHeadersRead endOfStream for stream id {}", streamId); + lifecycleManager.closeStreamRemote(stream, ctx.newSucceededFuture()); + } + logger.debug("onHeadersRead completed for stream id {}", streamId); + } + + @Override + public void onPriorityRead(ChannelHandlerContext ctx, int streamId, int streamDependency, short weight, + boolean exclusive) throws Http2Exception { + encoder.flowController().updateDependencyTree(streamId, streamDependency, weight, exclusive); + + listener.onPriorityRead(ctx, streamId, streamDependency, weight, exclusive); + } + + @Override + public void onRstStreamRead(ChannelHandlerContext ctx, int streamId, long errorCode) throws Http2Exception { + Http2Stream stream = connection.stream(streamId); + if (stream == null) { + verifyStreamMayHaveExisted(streamId, false, "RST_STREAM"); + return; + } + + switch (stream.state()) { + case IDLE: + throw connectionError(PROTOCOL_ERROR, "RST_STREAM received for IDLE stream %d", streamId); + case CLOSED: + return; // RST_STREAM frames must be ignored for closed streams. + default: + break; + } + + listener.onRstStreamRead(ctx, streamId, errorCode); + + lifecycleManager.closeStream(stream, ctx.newSucceededFuture()); + } + + @Override + public void onSettingsAckRead(ChannelHandlerContext ctx) throws Http2Exception { + // Apply oldest outstanding local settings here. This is a synchronization point between endpoints. + Http2Settings settings = encoder.pollSentSettings(); + + if (settings != null) { + applyLocalSettings(settings); + } + + listener.onSettingsAckRead(ctx); + } + + /** + * Applies settings sent from the local endpoint. + *

+ * This method is only called after the local settings have been acknowledged from the remote endpoint. + */ + private void applyLocalSettings(Http2Settings settings) throws Http2Exception { + Boolean pushEnabled = settings.pushEnabled(); + final Http2FrameReader.Configuration config = frameReader.configuration(); + final Http2HeadersDecoder.Configuration headerConfig = config.headersConfiguration(); + final Http2FrameSizePolicy frameSizePolicy = config.frameSizePolicy(); + if (pushEnabled != null) { + if (connection.isServer()) { + throw connectionError(PROTOCOL_ERROR, "Server sending SETTINGS frame with ENABLE_PUSH specified"); + } + connection.local().allowPushTo(pushEnabled); + } + + Long maxConcurrentStreams = settings.maxConcurrentStreams(); + if (maxConcurrentStreams != null) { + connection.remote().maxActiveStreams((int) Math.min(maxConcurrentStreams, MAX_VALUE)); + } + + Long headerTableSize = settings.headerTableSize(); + if (headerTableSize != null) { + headerConfig.maxHeaderTableSize(headerTableSize); + } + + Long maxHeaderListSize = settings.maxHeaderListSize(); + if (maxHeaderListSize != null) { + headerConfig.maxHeaderListSize(maxHeaderListSize, calculateMaxHeaderListSizeGoAway(maxHeaderListSize)); + } + + Integer maxFrameSize = settings.maxFrameSize(); + if (maxFrameSize != null) { + frameSizePolicy.maxFrameSize(maxFrameSize); + } + + Integer initialWindowSize = settings.initialWindowSize(); + if (initialWindowSize != null) { + flowController().initialWindowSize(initialWindowSize); + } + } + + @Override + public void onSettingsRead(final ChannelHandlerContext ctx, Http2Settings settings) throws Http2Exception { + if (settingsReceivedConsumer == null) { + // Acknowledge receipt of the settings. We should do this before we process the settings to ensure our + // remote peer applies these settings before any subsequent frames that we may send which depend upon + // these new settings. See https://github.com/netty/netty/issues/6520. + encoder.writeSettingsAck(ctx, ctx.newPromise()); + + encoder.remoteSettings(settings); + } else { + settingsReceivedConsumer.consumeReceivedSettings(settings); + } + + listener.onSettingsRead(ctx, settings); + } + + @Override + public void onPingRead(ChannelHandlerContext ctx, long data) throws Http2Exception { + if (autoAckPing) { + // Send an ack back to the remote client. + encoder.writePing(ctx, true, data, ctx.newPromise()); + } + listener.onPingRead(ctx, data); + } + + @Override + public void onPingAckRead(ChannelHandlerContext ctx, long data) throws Http2Exception { + listener.onPingAckRead(ctx, data); + } + + @Override + public void onPushPromiseRead(ChannelHandlerContext ctx, int streamId, int promisedStreamId, + Http2Headers headers, int padding) throws Http2Exception { + // A client cannot push. + if (connection().isServer()) { + throw connectionError(PROTOCOL_ERROR, "A client cannot push."); + } + + Http2Stream parentStream = connection.stream(streamId); + + if (shouldIgnoreHeadersOrDataFrame(ctx, streamId, parentStream, false, "PUSH_PROMISE")) { + return; + } + + switch (parentStream.state()) { + case OPEN: + case HALF_CLOSED_LOCAL: + // Allowed to receive push promise in these states. + break; + default: + // Connection error. + throw connectionError(PROTOCOL_ERROR, + "Stream %d in unexpected state for receiving push promise: %s", + parentStream.id(), parentStream.state()); + } + + if (!requestVerifier.isAuthoritative(ctx, headers)) { + throw streamError(promisedStreamId, PROTOCOL_ERROR, + "Promised request on stream %d for promised stream %d is not authoritative", + streamId, promisedStreamId); + } + if (!requestVerifier.isCacheable(headers)) { + throw streamError(promisedStreamId, PROTOCOL_ERROR, + "Promised request on stream %d for promised stream %d is not known to be cacheable", + streamId, promisedStreamId); + } + if (!requestVerifier.isSafe(headers)) { + throw streamError(promisedStreamId, PROTOCOL_ERROR, + "Promised request on stream %d for promised stream %d is not known to be safe", + streamId, promisedStreamId); + } + + // Reserve the push stream based with a priority based on the current stream's priority. + connection.remote().reservePushStream(promisedStreamId, parentStream); + + listener.onPushPromiseRead(ctx, streamId, promisedStreamId, headers, padding); + } + + @Override + public void onGoAwayRead(ChannelHandlerContext ctx, int lastStreamId, long errorCode, ByteBuf debugData) + throws Http2Exception { + onGoAwayRead0(ctx, lastStreamId, errorCode, debugData); + } + + @Override + public void onWindowUpdateRead(ChannelHandlerContext ctx, int streamId, int windowSizeIncrement) + throws Http2Exception { + Http2Stream stream = connection.stream(streamId); + if (stream == null || stream.state() == CLOSED || streamCreatedAfterGoAwaySent(streamId)) { + // Ignore this frame. + verifyStreamMayHaveExisted(streamId, false, "WINDOW_UPDATE"); + return; + } + + // Update the outbound flow control window. + encoder.flowController().incrementWindowSize(stream, windowSizeIncrement); + + listener.onWindowUpdateRead(ctx, streamId, windowSizeIncrement); + } + + @Override + public void onUnknownFrame(ChannelHandlerContext ctx, byte frameType, int streamId, Http2Flags flags, + ByteBuf payload) throws Http2Exception { + onUnknownFrame0(ctx, frameType, streamId, flags, payload); + } + + /** + * Helper method to determine if a frame that has the semantics of headers or data should be ignored for the + * {@code stream} (which may be {@code null}) associated with {@code streamId}. + */ + private boolean shouldIgnoreHeadersOrDataFrame(ChannelHandlerContext ctx, int streamId, Http2Stream stream, + boolean endOfStream, String frameName) throws Http2Exception { + if (stream == null) { + if (streamCreatedAfterGoAwaySent(streamId)) { + logger.info("{} ignoring {} frame for stream {}. Stream sent after GOAWAY sent", + ctx.channel(), frameName, streamId); + return true; + } + + // Make sure it's not an out-of-order frame, like a rogue DATA frame, for a stream that could + // never have existed. + verifyStreamMayHaveExisted(streamId, endOfStream, frameName); + + // Its possible that this frame would result in stream ID out of order creation (PROTOCOL ERROR) and its + // also possible that this frame is received on a CLOSED stream (STREAM_CLOSED after a RST_STREAM is + // sent). We don't have enough information to know for sure, so we choose the lesser of the two errors. + throw streamError(streamId, STREAM_CLOSED, "Received %s frame for an unknown stream %d", + frameName, streamId); + } + if (stream.isResetSent() || streamCreatedAfterGoAwaySent(streamId)) { + // If we have sent a reset stream it is assumed the stream will be closed after the write completes. + // If we have not sent a reset, but the stream was created after a GoAway this is not supported by + // DefaultHttp2Connection and if a custom Http2Connection is used it is assumed the lifetime is managed + // elsewhere so we don't close the stream or otherwise modify the stream's state. + + if (logger.isInfoEnabled()) { + logger.info("{} ignoring {} frame for stream {}", ctx.channel(), frameName, + stream.isResetSent() ? "RST_STREAM sent." : + "Stream created after GOAWAY sent. Last known stream by peer " + + connection.remote().lastStreamKnownByPeer()); + } + + return true; + } + return false; + } + + /** + * Helper method for determining whether or not to ignore inbound frames. A stream is considered to be created + * after a {@code GOAWAY} is sent if the following conditions hold: + *

+ *

    + *
  • A {@code GOAWAY} must have been sent by the local endpoint
    • + *
  • The {@code streamId} must identify a legitimate stream id for the remote endpoint to be creating
    • + *
  • {@code streamId} is greater than the Last Known Stream ID which was sent by the local endpoint + * in the last {@code GOAWAY} frame
    • + *
+ *

+ */ + private boolean streamCreatedAfterGoAwaySent(int streamId) { + Endpoint remote = connection.remote(); + return connection.goAwaySent() && remote.isValidStreamId(streamId) && + streamId > remote.lastStreamKnownByPeer(); + } + + private void verifyStreamMayHaveExisted(int streamId, boolean endOfStream, String frameName) + throws Http2Exception { + if (!connection.streamMayHaveExisted(streamId)) { + throw connectionError(PROTOCOL_ERROR, + "Stream %d does not exist for inbound frame %s, endOfStream = %b", + streamId, frameName, endOfStream); + } + } + } + + private final class PrefaceFrameListener implements Http2FrameListener { + /** + * Verifies that the HTTP/2 connection preface has been received from the remote endpoint. + * It is possible that the current call to + * {@link Http2FrameReader#readFrame(ChannelHandlerContext, ByteBuf, Http2FrameListener)} will have multiple + * frames to dispatch. So it may be OK for this class to get legitimate frames for the first readFrame. + */ + private void verifyPrefaceReceived() throws Http2Exception { + if (!prefaceReceived()) { + throw connectionError(PROTOCOL_ERROR, "Received non-SETTINGS as first frame."); + } + } + + @Override + public int onDataRead(ChannelHandlerContext ctx, int streamId, ByteBuf data, int padding, boolean endOfStream) + throws Http2Exception { + verifyPrefaceReceived(); + logger.debug("onDataRead streamId: {}, data readableBytes: {}, padding: {}, endOfStream: {}", + streamId, data.readableBytes(), padding, endOfStream); + logger.debug("onDataRead completed for stream id {}", streamId); + return internalFrameListener.onDataRead(ctx, streamId, data, padding, endOfStream); + } + + @Override + public void onHeadersRead(ChannelHandlerContext ctx, int streamId, Http2Headers headers, int padding, + boolean endOfStream) throws Http2Exception { + verifyPrefaceReceived(); + logger.debug("onHeadersRead (no priority) streamId: {}, padding: {}, endOfStream: {}, headers: {}", + streamId, padding, endOfStream, headers); + internalFrameListener.onHeadersRead(ctx, streamId, headers, padding, endOfStream); + logger.debug("onHeadersRead (no priority) completed for stream id {}", streamId); + } + + @Override + public void onHeadersRead(ChannelHandlerContext ctx, int streamId, Http2Headers headers, int streamDependency, + short weight, boolean exclusive, int padding, boolean endOfStream) throws Http2Exception { + verifyPrefaceReceived(); + logger.debug("onHeadersRead (with priority) streamId: {}, streamDependency: {}, weight: {}, " + + "exclusive: {}, padding: {}, endOfStream: {}, headers: {}", + streamId, streamDependency, weight, exclusive, padding, endOfStream, headers); + internalFrameListener.onHeadersRead(ctx, streamId, headers, streamDependency, weight, + exclusive, padding, endOfStream); + logger.debug("onHeadersRead (with priority) completed for stream id {}", streamId); + } + + @Override + public void onPriorityRead(ChannelHandlerContext ctx, int streamId, int streamDependency, short weight, + boolean exclusive) throws Http2Exception { + verifyPrefaceReceived(); + internalFrameListener.onPriorityRead(ctx, streamId, streamDependency, weight, exclusive); + } + + @Override + public void onRstStreamRead(ChannelHandlerContext ctx, int streamId, long errorCode) throws Http2Exception { + verifyPrefaceReceived(); + internalFrameListener.onRstStreamRead(ctx, streamId, errorCode); + } + + @Override + public void onSettingsAckRead(ChannelHandlerContext ctx) throws Http2Exception { + verifyPrefaceReceived(); + internalFrameListener.onSettingsAckRead(ctx); + } + + @Override + public void onSettingsRead(ChannelHandlerContext ctx, Http2Settings settings) throws Http2Exception { + // The first settings should change the internalFrameListener to the "real" listener + // that expects the preface to be verified. + if (!prefaceReceived()) { + internalFrameListener = new FrameReadListener(); + } + internalFrameListener.onSettingsRead(ctx, settings); + } + + @Override + public void onPingRead(ChannelHandlerContext ctx, long data) throws Http2Exception { + verifyPrefaceReceived(); + logger.debug("onPingRead data: {}", data); + internalFrameListener.onPingRead(ctx, data); + logger.debug("onPingRead completed for data {}", data); + } + + @Override + public void onPingAckRead(ChannelHandlerContext ctx, long data) throws Http2Exception { + verifyPrefaceReceived(); + logger.debug("onPingAckRead data: {}", data); + internalFrameListener.onPingAckRead(ctx, data); + logger.debug("onPingAckRead completed for data {}", data); + } + + @Override + public void onPushPromiseRead(ChannelHandlerContext ctx, int streamId, int promisedStreamId, + Http2Headers headers, int padding) throws Http2Exception { + verifyPrefaceReceived(); + logger.debug("onPushPromiseRead streamId: {}, promisedStreamId: {}, padding: {}, headers: {}", + streamId, promisedStreamId, padding, headers); + internalFrameListener.onPushPromiseRead(ctx, streamId, promisedStreamId, headers, padding); + logger.debug("onPushPromiseRead completed for promised stream id {}", promisedStreamId); + } + + @Override + public void onGoAwayRead(ChannelHandlerContext ctx, int lastStreamId, long errorCode, ByteBuf debugData) + throws Http2Exception { + logger.debug("onGoAwayRead lastStreamId: {}, errorCode: {}", lastStreamId, errorCode); + onGoAwayRead0(ctx, lastStreamId, errorCode, debugData); + logger.debug("onGoAwayRead completed"); + } + + @Override + public void onWindowUpdateRead(ChannelHandlerContext ctx, int streamId, int windowSizeIncrement) + throws Http2Exception { + verifyPrefaceReceived(); + logger.debug("onWindowUpdateRead streamId: {}, windowSizeIncrement: {}", + streamId, windowSizeIncrement); + internalFrameListener.onWindowUpdateRead(ctx, streamId, windowSizeIncrement); + logger.debug("onWindowUpdateRead completed for stream id {}", streamId); + } + + @Override + public void onUnknownFrame(ChannelHandlerContext ctx, byte frameType, int streamId, Http2Flags flags, + ByteBuf payload) throws Http2Exception { + onUnknownFrame0(ctx, frameType, streamId, flags, payload); + } + } +} diff --git a/framework/src/main/java/org/tron/common/client/DatabaseGrpcClient.java b/framework/src/main/java/org/tron/common/client/DatabaseGrpcClient.java index 0c22c264188..619b78af395 100644 --- a/framework/src/main/java/org/tron/common/client/DatabaseGrpcClient.java +++ b/framework/src/main/java/org/tron/common/client/DatabaseGrpcClient.java @@ -7,6 +7,8 @@ import org.tron.api.DatabaseGrpc; import org.tron.api.GrpcAPI.EmptyMessage; import org.tron.api.GrpcAPI.NumberMessage; +import org.tron.common.utils.DebugInterceptor; +import org.tron.common.utils.TimeoutInterceptor; import org.tron.protos.Protocol.Block; import org.tron.protos.Protocol.DynamicProperties; @@ -24,6 +26,7 @@ public class DatabaseGrpcClient { public DatabaseGrpcClient(String host, int port) { channel = ManagedChannelBuilder.forAddress(host, port) .usePlaintext() + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); databaseBlockingStub = DatabaseGrpc.newBlockingStub(channel); } @@ -31,6 +34,7 @@ public DatabaseGrpcClient(String host, int port) { public DatabaseGrpcClient(String host) { channel = ManagedChannelBuilder.forTarget(host) .usePlaintext() + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); databaseBlockingStub = DatabaseGrpc.newBlockingStub(channel); } diff --git a/framework/src/main/java/org/tron/core/services/RpcApiService.java b/framework/src/main/java/org/tron/core/services/RpcApiService.java index 63e7ba03fc7..651a51286e8 100755 --- a/framework/src/main/java/org/tron/core/services/RpcApiService.java +++ b/framework/src/main/java/org/tron/core/services/RpcApiService.java @@ -158,7 +158,7 @@ import org.tron.protos.contract.WitnessContract.WitnessUpdateContract; @Component -@Slf4j(topic = "API") +@Slf4j(topic = "grpcServer") public class RpcApiService extends RpcService { public static final String CONTRACT_VALIDATE_EXCEPTION = "ContractValidateException: {}"; @@ -213,6 +213,7 @@ protected void addService(NettyServerBuilder serverBuilder) { private void callContract(TriggerSmartContract request, StreamObserver responseObserver, boolean isConstant) { + logger.debug("callContract received request: isConstant={}", isConstant); TransactionExtention.Builder trxExtBuilder = TransactionExtention.newBuilder(); Return.Builder retBuilder = Return.newBuilder(); try { @@ -246,6 +247,7 @@ private void callContract(TriggerSmartContract request, } finally { responseObserver.onNext(trxExtBuilder.build()); responseObserver.onCompleted(); + logger.debug("callContract completed"); } } @@ -300,6 +302,7 @@ public class DatabaseApi extends DatabaseImplBase { @Override public void getBlockReference(org.tron.api.GrpcAPI.EmptyMessage request, io.grpc.stub.StreamObserver responseObserver) { + logger.debug("DatabaseApi.getBlockReference received request"); long headBlockNum = dbManager.getDynamicPropertiesStore() .getLatestBlockHeaderNumber(); byte[] blockHeaderHash = dbManager.getDynamicPropertiesStore() @@ -310,10 +313,12 @@ public void getBlockReference(org.tron.api.GrpcAPI.EmptyMessage request, .build(); responseObserver.onNext(ref); responseObserver.onCompleted(); + logger.debug("DatabaseApi.getBlockReference completed"); } @Override public void getNowBlock(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("DatabaseApi.getNowBlock received request"); Block block = null; try { block = chainBaseManager.getHead().getInstance(); @@ -322,10 +327,12 @@ public void getNowBlock(EmptyMessage request, StreamObserver responseObse } responseObserver.onNext(block); responseObserver.onCompleted(); + logger.debug("DatabaseApi.getNowBlock completed"); } @Override public void getBlockByNum(NumberMessage request, StreamObserver responseObserver) { + logger.debug("DatabaseApi.getBlockByNum received request: num={}", request.getNum()); Block block = null; try { block = chainBaseManager.getBlockByNum(request.getNum()).getInstance(); @@ -334,17 +341,20 @@ public void getBlockByNum(NumberMessage request, StreamObserver responseO } responseObserver.onNext(block); responseObserver.onCompleted(); + logger.debug("DatabaseApi.getBlockByNum completed"); } @Override public void getDynamicProperties(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("DatabaseApi.getDynamicProperties received request"); DynamicProperties.Builder builder = DynamicProperties.newBuilder(); builder.setLastSolidityBlockNum( dbManager.getDynamicPropertiesStore().getLatestSolidifiedBlockNum()); DynamicProperties dynamicProperties = builder.build(); responseObserver.onNext(dynamicProperties); responseObserver.onCompleted(); + logger.debug("DatabaseApi.getDynamicProperties completed"); } } @@ -355,6 +365,8 @@ public class WalletSolidityApi extends WalletSolidityImplBase { @Override public void getAccount(Account request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getAccount received request: address={}", + StringUtil.createReadableString(request.getAddress().toByteArray())); ByteString addressBs = request.getAddress(); if (addressBs != null) { Account reply = wallet.getAccount(request); @@ -363,10 +375,13 @@ public void getAccount(Account request, StreamObserver responseObserver responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getAccount completed"); } @Override public void getAccountById(Account request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getAccountById received request: accountId={}", + request.getAccountId().toStringUtf8()); ByteString id = request.getAccountId(); if (id != null) { Account reply = wallet.getAccountById(request); @@ -375,17 +390,23 @@ public void getAccountById(Account request, StreamObserver responseObse responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getAccountById completed"); } @Override public void listWitnesses(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.listWitnesses received request"); responseObserver.onNext(wallet.getWitnessList()); responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.listWitnesses completed"); } @Override public void getPaginatedNowWitnessList(PaginatedMessage request, StreamObserver responseObserver) { + logger.debug( + "WalletSolidityApi.getPaginatedNowWitnessList received request: offset={}, limit={}", + request.getOffset(), request.getLimit()); try { responseObserver.onNext( wallet.getPaginatedNowWitnessList(request.getOffset(), request.getLimit())); @@ -393,25 +414,33 @@ public void getPaginatedNowWitnessList(PaginatedMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getPaginatedNowWitnessList completed"); } @Override public void getAssetIssueList(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getAssetIssueList received request"); responseObserver.onNext(wallet.getAssetIssueList()); responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getAssetIssueList completed"); } @Override public void getPaginatedAssetIssueList(PaginatedMessage request, StreamObserver responseObserver) { + logger.debug( + "WalletSolidityApi.getPaginatedAssetIssueList received request: offset={}, limit={}", + request.getOffset(), request.getLimit()); responseObserver.onNext(wallet.getAssetIssueList(request.getOffset(), request.getLimit())); responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getPaginatedAssetIssueList completed"); } @Override public void getAssetIssueByName(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getAssetIssueByName received request"); ByteString assetName = request.getValue(); if (assetName != null) { try { @@ -424,11 +453,13 @@ public void getAssetIssueByName(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getAssetIssueByName completed"); } @Override public void getAssetIssueListByName(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getAssetIssueListByName received request"); ByteString assetName = request.getValue(); if (assetName != null) { @@ -437,11 +468,13 @@ public void getAssetIssueListByName(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getAssetIssueListByName completed"); } @Override public void getAssetIssueById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getAssetIssueById received request"); ByteString assetId = request.getValue(); if (assetId != null) { @@ -450,23 +483,29 @@ public void getAssetIssueById(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getAssetIssueById completed"); } @Override public void getNowBlock(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getNowBlock received request"); responseObserver.onNext(wallet.getNowBlock()); responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getNowBlock completed"); } @Override public void getNowBlock2(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getNowBlock2 received request"); responseObserver.onNext(block2Extention(wallet.getNowBlock())); responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getNowBlock2 completed"); } @Override public void getBlockByNum(NumberMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getBlockByNum received request: num={}", request.getNum()); long num = request.getNum(); if (num >= 0) { Block reply = wallet.getBlockByNum(num); @@ -475,11 +514,13 @@ public void getBlockByNum(NumberMessage request, StreamObserver responseO responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getBlockByNum completed"); } @Override public void getBlockByNum2(NumberMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getBlockByNum2 received request: num={}", request.getNum()); long num = request.getNum(); if (num >= 0) { Block reply = wallet.getBlockByNum(num); @@ -488,20 +529,31 @@ public void getBlockByNum2(NumberMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getBlockByNum2 completed"); } @Override public void getDelegatedResource(DelegatedResourceMessage request, StreamObserver responseObserver) { + logger.debug( + "WalletSolidityApi.getDelegatedResource received request: fromAddress={}, toAddress={}", + StringUtil.createReadableString(request.getFromAddress().toByteArray()), + StringUtil.createReadableString(request.getToAddress().toByteArray())); responseObserver .onNext(wallet.getDelegatedResource(request.getFromAddress(), request.getToAddress())); responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getDelegatedResource completed"); + } @Override public void getDelegatedResourceV2(DelegatedResourceMessage request, StreamObserver responseObserver) { + logger.debug( + "WalletSolidityApi.getDelegatedResourceV2 received request: fromAddress={}, toAddress={}", + StringUtil.createReadableString(request.getFromAddress().toByteArray()), + StringUtil.createReadableString(request.getToAddress().toByteArray())); try { responseObserver.onNext(wallet.getDelegatedResourceV2( request.getFromAddress(), request.getToAddress()) @@ -510,23 +562,27 @@ public void getDelegatedResourceV2(DelegatedResourceMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getDelegatedResourceV2 completed"); } @Override public void getDelegatedResourceAccountIndex(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getDelegatedResourceAccountIndex received request"); try { responseObserver .onNext(wallet.getDelegatedResourceAccountIndex(request.getValue())); } catch (Exception e) { - responseObserver.onError(getRunTimeException(e)); + responseObserver.onError(getRunTimeException(e)); //TODO Fix ME } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getDelegatedResourceAccountIndex completed"); } @Override public void getDelegatedResourceAccountIndexV2(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getDelegatedResourceAccountIndexV2 received request"); try { responseObserver .onNext(wallet.getDelegatedResourceAccountIndexV2(request.getValue())); @@ -534,11 +590,13 @@ public void getDelegatedResourceAccountIndexV2(BytesMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getDelegatedResourceAccountIndexV2 completed"); } @Override public void getCanDelegatedMaxSize(GrpcAPI.CanDelegatedMaxSizeRequestMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getCanDelegatedMaxSize received request"); try { responseObserver.onNext(wallet.getCanDelegatedMaxSize( request.getOwnerAddress(),request.getType())); @@ -546,11 +604,13 @@ public void getCanDelegatedMaxSize(GrpcAPI.CanDelegatedMaxSizeRequestMessage req responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getCanDelegatedMaxSize completed"); } @Override public void getAvailableUnfreezeCount(GrpcAPI.GetAvailableUnfreezeCountRequestMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getAvailableUnfreezeCount received request"); try { responseObserver.onNext(wallet.getAvailableUnfreezeCount( request.getOwnerAddress())); @@ -558,11 +618,13 @@ public void getAvailableUnfreezeCount(GrpcAPI.GetAvailableUnfreezeCountRequestMe responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getAvailableUnfreezeCount completed"); } @Override public void getCanWithdrawUnfreezeAmount(CanWithdrawUnfreezeAmountRequestMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getCanWithdrawUnfreezeAmount received request"); try { responseObserver .onNext(wallet.getCanWithdrawUnfreezeAmount( @@ -572,11 +634,13 @@ public void getCanWithdrawUnfreezeAmount(CanWithdrawUnfreezeAmountRequestMessage responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getCanWithdrawUnfreezeAmount completed"); } @Override public void getExchangeById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getExchangeById received request"); ByteString exchangeId = request.getValue(); if (Objects.nonNull(exchangeId)) { @@ -585,13 +649,16 @@ public void getExchangeById(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getExchangeById completed"); } @Override public void listExchanges(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.listExchanges received request"); responseObserver.onNext(wallet.getExchangeList()); responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.listExchanges completed"); } @Override @@ -603,6 +670,7 @@ public void getTransactionCountByBlockNum(NumberMessage request, @Override public void getTransactionById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getTransactionById received request"); ByteString id = request.getValue(); if (null != id) { Transaction reply = wallet.getTransactionById(id); @@ -612,11 +680,13 @@ public void getTransactionById(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getTransactionById completed"); } @Override public void getTransactionInfoById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getTransactionInfoById received request"); ByteString id = request.getValue(); if (null != id) { TransactionInfo reply = wallet.getTransactionInfoById(id); @@ -626,6 +696,7 @@ public void getTransactionInfoById(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getTransactionInfoById completed"); } @Override @@ -648,7 +719,7 @@ public void getBurnTrx(EmptyMessage request, StreamObserver respo @Override public void getMerkleTreeVoucherInfo(OutputPointInfo request, StreamObserver responseObserver) { - + logger.debug("WalletSolidityApi.getMerkleTreeVoucherInfo received request"); try { IncrementalMerkleVoucherInfo witnessInfo = wallet .getMerkleTreeVoucherInfo(request); @@ -657,11 +728,13 @@ public void getMerkleTreeVoucherInfo(OutputPointInfo request, responseObserver.onError(getRunTimeException(ex)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getMerkleTreeVoucherInfo completed"); } @Override public void scanNoteByIvk(GrpcAPI.IvkDecryptParameters request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.scanNoteByIvk received request"); long startNum = request.getStartBlockIndex(); long endNum = request.getEndBlockIndex(); @@ -673,11 +746,13 @@ public void scanNoteByIvk(GrpcAPI.IvkDecryptParameters request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.scanNoteByIvk completed"); } @Override public void scanAndMarkNoteByIvk(GrpcAPI.IvkDecryptAndMarkParameters request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.scanAndMarkNoteByIvk received request"); long startNum = request.getStartBlockIndex(); long endNum = request.getEndBlockIndex(); @@ -692,11 +767,13 @@ public void scanAndMarkNoteByIvk(GrpcAPI.IvkDecryptAndMarkParameters request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.scanAndMarkNoteByIvk completed"); } @Override public void scanNoteByOvk(GrpcAPI.OvkDecryptParameters request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.scanNoteByOvk received request"); long startNum = request.getStartBlockIndex(); long endNum = request.getEndBlockIndex(); try { @@ -707,21 +784,25 @@ public void scanNoteByOvk(GrpcAPI.OvkDecryptParameters request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.scanNoteByOvk completed"); } @Override public void isSpend(NoteParameters request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.isSpend received request"); try { responseObserver.onNext(wallet.isSpend(request)); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.isSpend completed"); } @Override public void scanShieldedTRC20NotesByIvk(IvkDecryptTRC20Parameters request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.scanShieldedTRC20NotesByIvk received request"); long startNum = request.getStartBlockIndex(); long endNum = request.getEndBlockIndex(); byte[] contractAddress = request.getShieldedTRC20ContractAddress().toByteArray(); @@ -739,11 +820,13 @@ public void scanShieldedTRC20NotesByIvk(IvkDecryptTRC20Parameters request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.scanShieldedTRC20NotesByIvk completed"); } @Override public void scanShieldedTRC20NotesByOvk(OvkDecryptTRC20Parameters request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.scanShieldedTRC20NotesByOvk received request"); long startNum = request.getStartBlockIndex(); long endNum = request.getEndBlockIndex(); byte[] contractAddress = request.getShieldedTRC20ContractAddress().toByteArray(); @@ -757,22 +840,26 @@ public void scanShieldedTRC20NotesByOvk(OvkDecryptTRC20Parameters request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.scanShieldedTRC20NotesByOvk completed"); } @Override public void isShieldedTRC20ContractNoteSpent(NfTRC20Parameters request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.isShieldedTRC20ContractNoteSpent received request"); try { responseObserver.onNext(wallet.isShieldedTRC20ContractNoteSpent(request)); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.isShieldedTRC20ContractNoteSpent completed"); } @Override public void getMarketOrderByAccount(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getMarketOrderByAccount received request"); try { ByteString address = request.getValue(); @@ -783,11 +870,13 @@ public void getMarketOrderByAccount(BytesMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getMarketOrderByAccount completed"); } @Override public void getMarketOrderById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getMarketOrderById received request"); try { ByteString address = request.getValue(); @@ -798,11 +887,13 @@ public void getMarketOrderById(BytesMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getMarketOrderById completed"); } @Override public void getMarketPriceByPair(MarketOrderPair request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getMarketPriceByPair received request"); try { MarketPriceList marketPriceList = wallet .getMarketPriceByPair(request.getSellTokenId().toByteArray(), @@ -812,11 +903,13 @@ public void getMarketPriceByPair(MarketOrderPair request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getMarketPriceByPair completed"); } @Override public void getMarketOrderListByPair(org.tron.protos.Protocol.MarketOrderPair request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getMarketOrderListByPair received request"); try { MarketOrderList orderPairList = wallet .getMarketOrderListByPair(request.getSellTokenId().toByteArray(), @@ -826,11 +919,13 @@ public void getMarketOrderListByPair(org.tron.protos.Protocol.MarketOrderPair re responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getMarketOrderListByPair completed"); } @Override public void getMarketPairList(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getMarketPairList received request"); try { MarketOrderPairList pairList = wallet.getMarketPairList(); responseObserver.onNext(pairList); @@ -838,6 +933,7 @@ public void getMarketPairList(EmptyMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getMarketPairList completed"); } @Override @@ -850,6 +946,7 @@ public void triggerConstantContract(TriggerSmartContract request, @Override public void estimateEnergy(TriggerSmartContract request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.estimateEnergy received request"); TransactionExtention.Builder trxExtBuilder = TransactionExtention.newBuilder(); Return.Builder retBuilder = Return.newBuilder(); EstimateEnergyMessage.Builder estimateBuilder @@ -876,12 +973,15 @@ public void estimateEnergy(TriggerSmartContract request, estimateBuilder.setResult(retBuilder); responseObserver.onNext(estimateBuilder.build()); responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.estimateEnergy completed"); } } @Override public void getTransactionInfoByBlockNum(NumberMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getTransactionInfoByBlockNum received request: num={}", + request.getNum()); try { responseObserver.onNext(wallet.getTransactionInfoByBlockNum(request.getNum())); } catch (Exception e) { @@ -889,6 +989,7 @@ public void getTransactionInfoByBlockNum(NumberMessage request, } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getTransactionInfoByBlockNum completed"); } @Override @@ -900,23 +1001,27 @@ public void getBlock(GrpcAPI.BlockReq request, @Override public void getBandwidthPrices(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getBandwidthPrices received request"); try { responseObserver.onNext(wallet.getBandwidthPrices()); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getBandwidthPrices completed"); } @Override public void getEnergyPrices(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletSolidityApi.getEnergyPrices received request"); try { responseObserver.onNext(wallet.getEnergyPrices()); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletSolidityApi.getEnergyPrices completed"); } } @@ -955,6 +1060,8 @@ private BlockListExtention blockList2Extention(BlockList blockList) { @Override public void getAccount(Account req, StreamObserver responseObserver) { + logger.debug("WalletApi.getAccount received request: address={}", + StringUtil.createReadableString(req.getAddress().toByteArray())); ByteString addressBs = req.getAddress(); if (addressBs != null) { Account reply = wallet.getAccount(req); @@ -963,10 +1070,13 @@ public void getAccount(Account req, StreamObserver responseObserver) { responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getAccount completed"); } @Override public void getAccountById(Account req, StreamObserver responseObserver) { + logger.debug("WalletApi.getAccountById received request: accountId={}", + req.getAccountId().toStringUtf8()); ByteString accountId = req.getAccountId(); if (accountId != null) { Account reply = wallet.getAccountById(req); @@ -975,6 +1085,7 @@ public void getAccountById(Account req, StreamObserver responseObserver responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getAccountById completed"); } /** @@ -982,6 +1093,7 @@ public void getAccountById(Account req, StreamObserver responseObserver */ public void getAccountBalance(AccountBalanceRequest request, StreamObserver responseObserver) { + logger.debug("WalletApi.getAccountBalance received request"); try { AccountBalanceResponse accountBalanceResponse = wallet.getAccountBalance(request); responseObserver.onNext(accountBalanceResponse); @@ -989,6 +1101,7 @@ public void getAccountBalance(AccountBalanceRequest request, } catch (Exception e) { responseObserver.onError(e); } + logger.debug("WalletApi.getAccountBalance completed"); } /** @@ -996,6 +1109,7 @@ public void getAccountBalance(AccountBalanceRequest request, */ public void getBlockBalanceTrace(BlockBalanceTrace.BlockIdentifier request, StreamObserver responseObserver) { + logger.debug("WalletApi.getBlockBalanceTrace received request"); try { BlockBalanceTrace blockBalanceTrace = wallet.getBlockBalance(request); responseObserver.onNext(blockBalanceTrace); @@ -1003,11 +1117,13 @@ public void getBlockBalanceTrace(BlockBalanceTrace.BlockIdentifier request, } catch (Exception e) { responseObserver.onError(e); } + logger.debug("WalletApi.getBlockBalanceTrace completed"); } @Override public void createTransaction(TransferContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.createTransaction received request"); try { responseObserver .onNext( @@ -1018,6 +1134,7 @@ public void createTransaction(TransferContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.createTransaction response completed"); } @Override @@ -1028,6 +1145,8 @@ public void createTransaction2(TransferContract request, private void createTransactionExtention(Message request, ContractType contractType, StreamObserver responseObserver) { + logger.debug("WalletApi.createTransactionExtention received request for contract type: {}", + contractType); TransactionExtention.Builder trxExtBuilder = TransactionExtention.newBuilder(); Return.Builder retBuilder = Return.newBuilder(); try { @@ -1048,35 +1167,44 @@ private void createTransactionExtention(Message request, ContractType contractTy trxExtBuilder.setResult(retBuilder); responseObserver.onNext(trxExtBuilder.build()); responseObserver.onCompleted(); + logger.debug("WalletApi.createTransactionExtention completed for contract type: {}", + contractType); } @Override public void getTransactionSignWeight(Transaction req, StreamObserver responseObserver) { + logger.debug("WalletApi.getTransactionSignWeight received request"); TransactionSignWeight tsw = transactionUtil.getTransactionSignWeight(req); responseObserver.onNext(tsw); responseObserver.onCompleted(); + logger.debug("WalletApi.getTransactionSignWeight response completed"); } @Override public void getTransactionApprovedList(Transaction req, StreamObserver responseObserver) { + logger.debug("WalletApi.getTransactionApprovedList received request"); TransactionApprovedList tal = wallet.getTransactionApprovedList(req); responseObserver.onNext(tal); responseObserver.onCompleted(); + logger.debug("WalletApi.getTransactionApprovedList response completed"); } @Override public void broadcastTransaction(Transaction req, StreamObserver responseObserver) { + logger.debug("WalletApi.broadcastTransaction received request"); GrpcAPI.Return result = wallet.broadcastTransaction(req); responseObserver.onNext(result); responseObserver.onCompleted(); + logger.debug("WalletApi.broadcastTransaction response completed"); } @Override public void createAssetIssue(AssetIssueContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.createAssetIssue received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.AssetIssueContract).getInstance()); @@ -1085,6 +1213,7 @@ public void createAssetIssue(AssetIssueContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.createAssetIssue response completed"); } @Override @@ -1096,6 +1225,7 @@ public void createAssetIssue2(AssetIssueContract request, @Override public void unfreezeAsset(UnfreezeAssetContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.unfreezeAsset received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.UnfreezeAssetContract).getInstance()); @@ -1104,6 +1234,7 @@ public void unfreezeAsset(UnfreezeAssetContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.unfreezeAsset response completed"); } @Override @@ -1148,6 +1279,7 @@ private void checkVoteWitnessAccount(VoteWitnessContract req) { @Override public void voteWitnessAccount(VoteWitnessContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.voteWitnessAccount received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.VoteWitnessContract).getInstance()); @@ -1157,6 +1289,7 @@ public void voteWitnessAccount(VoteWitnessContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.voteWitnessAccount response completed"); } @Override @@ -1189,6 +1322,7 @@ public void clearContractABI(ClearABIContract request, @Override public void createWitness(WitnessCreateContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.createWitness received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.WitnessCreateContract).getInstance()); @@ -1198,6 +1332,7 @@ public void createWitness(WitnessCreateContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.createWitness response completed"); } @Override @@ -1209,6 +1344,7 @@ public void createWitness2(WitnessCreateContract request, @Override public void createAccount(AccountCreateContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.createAccount received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.AccountCreateContract).getInstance()); @@ -1218,6 +1354,7 @@ public void createAccount(AccountCreateContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.createAccount response completed"); } @Override @@ -1229,6 +1366,7 @@ public void createAccount2(AccountCreateContract request, @Override public void updateWitness(WitnessUpdateContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.updateWitness received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.WitnessUpdateContract).getInstance()); @@ -1238,6 +1376,7 @@ public void updateWitness(WitnessUpdateContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.updateWitness response completed"); } @Override @@ -1249,6 +1388,7 @@ public void updateWitness2(WitnessUpdateContract request, @Override public void updateAccount(AccountUpdateContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.updateAccount received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.AccountUpdateContract).getInstance()); @@ -1258,11 +1398,13 @@ public void updateAccount(AccountUpdateContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.updateAccount response completed"); } @Override public void setAccountId(SetAccountIdContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.setAccountId received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.SetAccountIdContract).getInstance()); @@ -1272,6 +1414,7 @@ public void setAccountId(SetAccountIdContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.setAccountId response completed"); } @Override @@ -1283,6 +1426,7 @@ public void updateAccount2(AccountUpdateContract request, @Override public void updateAsset(UpdateAssetContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.updateAsset received request"); try { responseObserver.onNext( createTransactionCapsule(request, @@ -1293,6 +1437,7 @@ public void updateAsset(UpdateAssetContract request, logger.debug("ContractValidateException", e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.updateAsset response completed"); } @Override @@ -1304,6 +1449,7 @@ public void updateAsset2(UpdateAssetContract request, @Override public void freezeBalance(FreezeBalanceContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.freezeBalance received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.FreezeBalanceContract).getInstance()); @@ -1313,6 +1459,7 @@ public void freezeBalance(FreezeBalanceContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.freezeBalance response completed"); } @Override @@ -1330,6 +1477,7 @@ public void freezeBalanceV2(BalanceContract.FreezeBalanceV2Contract request, @Override public void unfreezeBalance(UnfreezeBalanceContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.unfreezeBalance received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.UnfreezeBalanceContract) @@ -1340,6 +1488,7 @@ public void unfreezeBalance(UnfreezeBalanceContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.unfreezeBalance response completed"); } @Override @@ -1357,6 +1506,7 @@ public void unfreezeBalanceV2(BalanceContract.UnfreezeBalanceV2Contract request, @Override public void withdrawBalance(WithdrawBalanceContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.withdrawBalance received request"); try { responseObserver.onNext( createTransactionCapsule(request, ContractType.WithdrawBalanceContract) @@ -1367,6 +1517,7 @@ public void withdrawBalance(WithdrawBalanceContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.withdrawBalance response completed"); } @Override @@ -1450,30 +1601,42 @@ public void exchangeTransaction(ExchangeTransactionContract request, @Override public void getNowBlock(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getNowBlock received request"); responseObserver.onNext(wallet.getNowBlock()); responseObserver.onCompleted(); + logger.debug("WalletApi.getNowBlock response completed"); } @Override public void getNowBlock2(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getNowBlock2 received request"); Block block = wallet.getNowBlock(); responseObserver.onNext(block2Extention(block)); responseObserver.onCompleted(); + logger.debug("WalletApi.getNowBlock2 response completed"); } @Override public void getBlockByNum(NumberMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getBlockByNum received request for block num: {}", + request.getNum()); responseObserver.onNext(wallet.getBlockByNum(request.getNum())); responseObserver.onCompleted(); + logger.debug("WalletApi.getBlockByNum response completed for block num: {}", + request.getNum()); } @Override public void getBlockByNum2(NumberMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getBlockByNum2 received request for block num: {}", + request.getNum()); Block block = wallet.getBlockByNum(request.getNum()); responseObserver.onNext(block2Extention(block)); responseObserver.onCompleted(); + logger.debug("WalletApi.getBlockByNum2 response completed for block num: {}", + request.getNum()); } @Override @@ -1484,13 +1647,16 @@ public void getTransactionCountByBlockNum(NumberMessage request, @Override public void listNodes(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.listNodes received request"); responseObserver.onNext(wallet.listNodes()); responseObserver.onCompleted(); + logger.debug("WalletApi.listNodes response completed"); } @Override public void transferAsset(TransferAssetContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.transferAsset received request"); try { responseObserver .onNext(createTransactionCapsule(request, ContractType.TransferAssetContract) @@ -1501,6 +1667,7 @@ public void transferAsset(TransferAssetContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.transferAsset response completed"); } @Override @@ -1512,6 +1679,7 @@ public void transferAsset2(TransferAssetContract request, @Override public void participateAssetIssue(ParticipateAssetIssueContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.participateAssetIssue received request"); try { responseObserver .onNext(createTransactionCapsule(request, ContractType.ParticipateAssetIssueContract) @@ -1522,6 +1690,7 @@ public void participateAssetIssue(ParticipateAssetIssueContract request, logger.debug(CONTRACT_VALIDATE_EXCEPTION, e.getMessage()); } responseObserver.onCompleted(); + logger.debug("WalletApi.participateAssetIssue response completed"); } @Override @@ -1534,6 +1703,7 @@ public void participateAssetIssue2(ParticipateAssetIssueContract request, @Override public void getAssetIssueByAccount(Account request, StreamObserver responseObserver) { + logger.debug("WalletApi.getAssetIssueByAccount received request"); ByteString fromBs = request.getAddress(); if (fromBs != null) { @@ -1542,11 +1712,13 @@ public void getAssetIssueByAccount(Account request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getAssetIssueByAccount response completed"); } @Override public void getAccountNet(Account request, StreamObserver responseObserver) { + logger.debug("WalletApi.getAccountNet received request"); ByteString fromBs = request.getAddress(); if (fromBs != null) { @@ -1555,11 +1727,13 @@ public void getAccountNet(Account request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("gWalletApi.etAccountNet response completed"); } @Override public void getAccountResource(Account request, StreamObserver responseObserver) { + logger.debug("WalletApi.getAccountResource received request"); ByteString fromBs = request.getAddress(); if (fromBs != null) { @@ -1568,11 +1742,13 @@ public void getAccountResource(Account request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getAccountResource response completed"); } @Override public void getAssetIssueByName(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getAssetIssueByName received request"); ByteString assetName = request.getValue(); if (assetName != null) { try { @@ -1585,11 +1761,13 @@ public void getAssetIssueByName(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("gWalletApi.etAssetIssueByName response completed"); } @Override public void getAssetIssueListByName(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getAssetIssueListByName received request"); ByteString assetName = request.getValue(); if (assetName != null) { @@ -1598,11 +1776,13 @@ public void getAssetIssueListByName(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getAssetIssueListByName response completed"); } @Override public void getAssetIssueById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getAssetIssueById received request"); ByteString assetId = request.getValue(); if (assetId != null) { @@ -1611,10 +1791,12 @@ public void getAssetIssueById(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getAssetIssueById response completed"); } @Override public void getBlockById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getBlockById received request"); ByteString blockId = request.getValue(); if (Objects.nonNull(blockId)) { @@ -1623,11 +1805,13 @@ public void getBlockById(BytesMessage request, StreamObserver responseObs responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getBlockById response completed"); } @Override public void getProposalById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getProposalById received request"); ByteString proposalId = request.getValue(); if (Objects.nonNull(proposalId)) { @@ -1636,11 +1820,13 @@ public void getProposalById(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getProposalById response completed"); } @Override public void getExchangeById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getExchangeById received request"); ByteString exchangeId = request.getValue(); if (Objects.nonNull(exchangeId)) { @@ -1649,11 +1835,13 @@ public void getExchangeById(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getExchangeById response completed"); } @Override public void getBlockByLimitNext(BlockLimit request, StreamObserver responseObserver) { + logger.debug("WalletApi.getBlockByLimitNext received request"); long startNum = request.getStartNum(); long endNum = request.getEndNum(); @@ -1663,11 +1851,13 @@ public void getBlockByLimitNext(BlockLimit request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getBlockByLimitNext response completed"); } @Override public void getBlockByLimitNext2(BlockLimit request, StreamObserver responseObserver) { + logger.debug("WalletApi.getBlockByLimitNext2 received request"); long startNum = request.getStartNum(); long endNum = request.getEndNum(); @@ -1678,11 +1868,13 @@ public void getBlockByLimitNext2(BlockLimit request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getBlockByLimitNext2 response completed"); } @Override public void getBlockByLatestNum(NumberMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getBlockByLatestNum received request"); long getNum = request.getNum(); if (getNum > 0 && getNum < BLOCK_LIMIT_NUM) { @@ -1691,11 +1883,13 @@ public void getBlockByLatestNum(NumberMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getBlockByLatestNum response completed"); } @Override public void getBlockByLatestNum2(NumberMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getBlockByLatestNum2 received request"); long getNum = request.getNum(); if (getNum > 0 && getNum < BLOCK_LIMIT_NUM) { @@ -1704,11 +1898,13 @@ public void getBlockByLatestNum2(NumberMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getBlockByLatestNum2 response completed"); } @Override public void getTransactionById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getTransactionById received request"); ByteString transactionId = request.getValue(); if (Objects.nonNull(transactionId)) { @@ -1717,6 +1913,7 @@ public void getTransactionById(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getTransactionById response completed"); } @Override @@ -1725,24 +1922,31 @@ public void deployContract(CreateSmartContract request, createTransactionExtention(request, ContractType.CreateSmartContract, responseObserver); } + @Override public void totalTransaction(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.totalTransaction received request"); responseObserver.onNext(wallet.totalTransaction()); responseObserver.onCompleted(); + logger.debug("WalletApi.totalTransaction response completed"); } @Override public void getNextMaintenanceTime(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getNextMaintenanceTime received request"); responseObserver.onNext(wallet.getNextMaintenanceTime()); responseObserver.onCompleted(); + logger.debug("WalletApi.getNextMaintenanceTime response completed"); } @Override public void getAssetIssueList(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getAssetIssueList received request"); responseObserver.onNext(wallet.getAssetIssueList()); responseObserver.onCompleted(); + logger.debug("WalletApi.getAssetIssueList response completed"); } @Override @@ -1755,6 +1959,7 @@ public void triggerContract(TriggerSmartContract request, @Override public void estimateEnergy(TriggerSmartContract request, StreamObserver responseObserver) { + logger.debug("WalletApi.estimateEnergy received request"); TransactionExtention.Builder trxExtBuilder = TransactionExtention.newBuilder(); Return.Builder retBuilder = Return.newBuilder(); EstimateEnergyMessage.Builder estimateBuilder @@ -1781,6 +1986,7 @@ public void estimateEnergy(TriggerSmartContract request, estimateBuilder.setResult(retBuilder); responseObserver.onNext(estimateBuilder.build()); responseObserver.onCompleted(); + logger.debug("WalletApi.estimateEnergy response completed"); } } @@ -1793,6 +1999,7 @@ public void triggerConstantContract(TriggerSmartContract request, private void callContract(TriggerSmartContract request, StreamObserver responseObserver, boolean isConstant) { + logger.debug("WalletApi.callContract received request, isConstant: {}", isConstant); TransactionExtention.Builder trxExtBuilder = TransactionExtention.newBuilder(); Return.Builder retBuilder = Return.newBuilder(); try { @@ -1827,40 +2034,50 @@ private void callContract(TriggerSmartContract request, } finally { responseObserver.onNext(trxExtBuilder.build()); responseObserver.onCompleted(); + logger.debug("WalletApi.callContract response completed, isConstant: {}", isConstant); } } public void getPaginatedAssetIssueList(PaginatedMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getPaginatedAssetIssueList request received"); responseObserver.onNext(wallet.getAssetIssueList(request.getOffset(), request.getLimit())); responseObserver.onCompleted(); + logger.debug("WalletApi.getPaginatedAssetIssueList response completed"); } @Override public void getContract(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getContract request received"); SmartContract contract = wallet.getContract(request); responseObserver.onNext(contract); responseObserver.onCompleted(); + logger.debug("WalletApi.getContract response completed"); } @Override public void getContractInfo(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getContractInfo request received"); SmartContractDataWrapper contract = wallet.getContractInfo(request); responseObserver.onNext(contract); responseObserver.onCompleted(); + logger.debug("WalletApi.getContractInfo response completed"); } public void listWitnesses(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.listWitnesses request received"); responseObserver.onNext(wallet.getWitnessList()); responseObserver.onCompleted(); + logger.debug("WalletApi.listWitnesses response completed"); } @Override public void getPaginatedNowWitnessList(PaginatedMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getPaginatedNowWitnessList request received"); try { responseObserver.onNext( wallet.getPaginatedNowWitnessList(request.getOffset(), request.getLimit())); @@ -1868,27 +2085,33 @@ public void getPaginatedNowWitnessList(PaginatedMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getPaginatedNowWitnessList response completed"); } @Override public void listProposals(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.listProposals request received"); responseObserver.onNext(wallet.getProposalList()); responseObserver.onCompleted(); + logger.debug("WalletApi.listProposals response completed"); } @Override public void getDelegatedResource(DelegatedResourceMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getDelegatedResource request received"); responseObserver .onNext(wallet.getDelegatedResource(request.getFromAddress(), request.getToAddress())); responseObserver.onCompleted(); + logger.debug("WalletApi.getDelegatedResource response completed"); } @Override public void getDelegatedResourceV2(DelegatedResourceMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getDelegatedResourceV2 request received"); try { responseObserver.onNext(wallet.getDelegatedResourceV2( request.getFromAddress(), request.getToAddress()) @@ -1897,11 +2120,13 @@ public void getDelegatedResourceV2(DelegatedResourceMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getDelegatedResourceV2 response completed"); } @Override public void getDelegatedResourceAccountIndex(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getDelegatedResourceAccountIndex request received"); try { responseObserver .onNext(wallet.getDelegatedResourceAccountIndex(request.getValue())); @@ -1909,11 +2134,13 @@ public void getDelegatedResourceAccountIndex(BytesMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getDelegatedResourceAccountIndex response completed"); } @Override public void getDelegatedResourceAccountIndexV2(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getDelegatedResourceAccountIndexV2 request received"); try { responseObserver .onNext(wallet.getDelegatedResourceAccountIndexV2(request.getValue())); @@ -1921,11 +2148,13 @@ public void getDelegatedResourceAccountIndexV2(BytesMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getDelegatedResourceAccountIndexV2 response completed"); } @Override public void getCanDelegatedMaxSize(GrpcAPI.CanDelegatedMaxSizeRequestMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getCanDelegatedMaxSize request received"); try { responseObserver.onNext(wallet.getCanDelegatedMaxSize( request.getOwnerAddress(), request.getType())); @@ -1934,11 +2163,13 @@ public void getCanDelegatedMaxSize(GrpcAPI.CanDelegatedMaxSizeRequestMessage req } responseObserver.onCompleted(); + logger.debug("WalletApi.getCanDelegatedMaxSize response completed"); } @Override public void getAvailableUnfreezeCount(GrpcAPI.GetAvailableUnfreezeCountRequestMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getAvailableUnfreezeCount request received"); try { responseObserver.onNext(wallet.getAvailableUnfreezeCount( request.getOwnerAddress())); @@ -1947,11 +2178,13 @@ public void getAvailableUnfreezeCount(GrpcAPI.GetAvailableUnfreezeCountRequestMe } responseObserver.onCompleted(); + logger.debug("WalletApi.getAvailableUnfreezeCount response completed"); } @Override public void getCanWithdrawUnfreezeAmount(CanWithdrawUnfreezeAmountRequestMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getCanWithdrawUnfreezeAmount request received"); try { responseObserver .onNext(wallet.getCanWithdrawUnfreezeAmount( @@ -1961,76 +2194,92 @@ public void getCanWithdrawUnfreezeAmount(CanWithdrawUnfreezeAmountRequestMessage responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getCanWithdrawUnfreezeAmount response completed"); } @Override public void getBandwidthPrices(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getBandwidthPrices request received"); try { responseObserver.onNext(wallet.getBandwidthPrices()); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getBandwidthPrices response completed"); } @Override public void getEnergyPrices(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getEnergyPrices request received"); try { responseObserver.onNext(wallet.getEnergyPrices()); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getEnergyPrices response completed"); } @Override public void getMemoFee(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getMemoFee request received"); try { responseObserver.onNext(wallet.getMemoFeePrices()); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getMemoFee response completed"); } @Override public void getPaginatedProposalList(PaginatedMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getPaginatedProposalList request received"); responseObserver .onNext(wallet.getPaginatedProposalList(request.getOffset(), request.getLimit())); responseObserver.onCompleted(); + logger.debug("WalletApi.getPaginatedProposalList response completed"); } @Override public void getPaginatedExchangeList(PaginatedMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getPaginatedExchangeList request received"); responseObserver .onNext(wallet.getPaginatedExchangeList(request.getOffset(), request.getLimit())); responseObserver.onCompleted(); + logger.debug("WalletApi.getPaginatedExchangeList response completed"); } @Override public void listExchanges(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.listExchanges request received"); responseObserver.onNext(wallet.getExchangeList()); responseObserver.onCompleted(); + logger.debug("WalletApi.listExchanges response completed"); } @Override public void getChainParameters(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getChainParameters request received"); responseObserver.onNext(wallet.getChainParameters()); responseObserver.onCompleted(); + logger.debug("WalletApi.getChainParameters response completed"); } @Override public void getTransactionInfoById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getTransactionInfoById request received"); ByteString id = request.getValue(); if (null != id) { TransactionInfo reply = wallet.getTransactionInfoById(id); @@ -2040,16 +2289,19 @@ public void getTransactionInfoById(BytesMessage request, responseObserver.onNext(null); } responseObserver.onCompleted(); + logger.debug("WalletApi.getTransactionInfoById response completed"); } @Override public void getNodeInfo(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getNodeInfo request received"); try { responseObserver.onNext(nodeInfoService.getNodeInfo().transferToProtoEntity()); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getNodeInfo response completed"); } @Override @@ -2062,23 +2314,25 @@ public void accountPermissionUpdate(AccountPermissionUpdateContract request, @Override public void getMerkleTreeVoucherInfo(OutputPointInfo request, StreamObserver responseObserver) { - + logger.debug("WalletApi.getMerkleTreeVoucherInfo request received"); try { IncrementalMerkleVoucherInfo witnessInfo = wallet .getMerkleTreeVoucherInfo(request); responseObserver.onNext(witnessInfo); } catch (Exception ex) { responseObserver.onError(getRunTimeException(ex)); + logger.debug("WalletApi.getMerkleTreeVoucherInfo response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getMerkleTreeVoucherInfo response completed"); } @Override public void createShieldedTransaction(PrivateParameters request, StreamObserver responseObserver) { - + logger.debug("WalletApi.createShieldedTransaction request received"); TransactionExtention.Builder trxExtBuilder = TransactionExtention.newBuilder(); Return.Builder retBuilder = Return.newBuilder(); @@ -2101,13 +2355,14 @@ public void createShieldedTransaction(PrivateParameters request, trxExtBuilder.setResult(retBuilder); responseObserver.onNext(trxExtBuilder.build()); responseObserver.onCompleted(); + logger.debug("WalletApi.createShieldedTransaction response completed"); } @Override public void createShieldedTransactionWithoutSpendAuthSig(PrivateParametersWithoutAsk request, StreamObserver responseObserver) { - + logger.debug("WalletApi.createShieldedTransactionWithoutSpendAuthSig request received"); TransactionExtention.Builder trxExtBuilder = TransactionExtention.newBuilder(); Return.Builder retBuilder = Return.newBuilder(); @@ -2131,49 +2386,59 @@ public void createShieldedTransactionWithoutSpendAuthSig(PrivateParametersWithou trxExtBuilder.setResult(retBuilder); responseObserver.onNext(trxExtBuilder.build()); responseObserver.onCompleted(); + logger.debug("WalletApi.createShieldedTransactionWithoutSpendAuthSig response completed"); } @Override public void getNewShieldedAddress(EmptyMessage request, StreamObserver responseObserver) { - + logger.debug("WalletApi.getNewShieldedAddress request received"); try { responseObserver.onNext(wallet.getNewShieldedAddress()); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.getNewShieldedAddress response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getNewShieldedAddress response completed"); } @Override public void getSpendingKey(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getSpendingKey request received"); try { responseObserver.onNext(wallet.getSpendingKey()); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.getSpendingKey response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getSpendingKey response completed"); } @Override public void getRcm(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getRcm request received"); try { responseObserver.onNext(wallet.getRcm()); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.getRcm response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getRcm response completed"); } @Override public void getExpandedSpendingKey(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getExpandedSpendingKey request received"); ByteString spendingKey = request.getValue(); try { @@ -2181,43 +2446,52 @@ public void getExpandedSpendingKey(BytesMessage request, responseObserver.onNext(response); } catch (BadItemException | ZksnarkException e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.getExpandedSpendingKey response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getExpandedSpendingKey response completed"); } @Override public void getAkFromAsk(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getAkFromAsk request received"); ByteString ak = request.getValue(); try { responseObserver.onNext(wallet.getAkFromAsk(ak)); } catch (BadItemException | ZksnarkException e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.getAkFromAsk response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getAkFromAsk response completed"); } @Override public void getNkFromNsk(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getNkFromNsk request received"); ByteString nk = request.getValue(); try { responseObserver.onNext(wallet.getNkFromNsk(nk)); } catch (BadItemException | ZksnarkException e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.getNkFromNsk response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getNkFromNsk response completed"); } @Override public void getIncomingViewingKey(ViewingKeyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getIncomingViewingKey request received"); ByteString ak = request.getAk(); ByteString nk = request.getNk(); @@ -2225,29 +2499,35 @@ public void getIncomingViewingKey(ViewingKeyMessage request, responseObserver.onNext(wallet.getIncomingViewingKey(ak.toByteArray(), nk.toByteArray())); } catch (ZksnarkException e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.getIncomingViewingKey response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getIncomingViewingKey response completed"); } @Override public void getDiversifier(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getDiversifier request received"); try { DiversifierMessage d = wallet.getDiversifier(); responseObserver.onNext(d); } catch (ZksnarkException e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.getDiversifier response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getDiversifier response completed"); } @Override public void getZenPaymentAddress(IncomingViewingKeyDiversifierMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getZenPaymentAddress request received"); IncomingViewingKeyMessage ivk = request.getIvk(); DiversifierMessage d = request.getD(); @@ -2259,15 +2539,18 @@ public void getZenPaymentAddress(IncomingViewingKeyDiversifierMessage request, responseObserver.onNext(saplingPaymentAddressMessage); } catch (BadItemException | ZksnarkException e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.getZenPaymentAddress response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getZenPaymentAddress response completed"); } @Override public void scanNoteByIvk(GrpcAPI.IvkDecryptParameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.scanNoteByIvk request received"); long startNum = request.getStartBlockIndex(); long endNum = request.getEndBlockIndex(); @@ -2277,15 +2560,18 @@ public void scanNoteByIvk(GrpcAPI.IvkDecryptParameters request, responseObserver.onNext(decryptNotes); } catch (BadItemException | ZksnarkException e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.scanNoteByIvk response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.scanNoteByIvk response completed"); } @Override public void scanAndMarkNoteByIvk(GrpcAPI.IvkDecryptAndMarkParameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.scanAndMarkNoteByIvk request received"); long startNum = request.getStartBlockIndex(); long endNum = request.getEndBlockIndex(); @@ -2298,14 +2584,17 @@ public void scanAndMarkNoteByIvk(GrpcAPI.IvkDecryptAndMarkParameters request, } catch (BadItemException | ZksnarkException | InvalidProtocolBufferException | ItemNotFoundException e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.scanAndMarkNoteByIvk response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.scanAndMarkNoteByIvk response completed"); } @Override public void scanNoteByOvk(GrpcAPI.OvkDecryptParameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.scanNoteByOvk request received"); long startNum = request.getStartBlockIndex(); long endNum = request.getEndBlockIndex(); @@ -2315,66 +2604,81 @@ public void scanNoteByOvk(GrpcAPI.OvkDecryptParameters request, responseObserver.onNext(decryptNotes); } catch (BadItemException | ZksnarkException e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.scanNoteByOvk response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.scanNoteByOvk response completed"); } @Override public void isSpend(NoteParameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.isSpend request received"); try { responseObserver.onNext(wallet.isSpend(request)); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.isSpend response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.isSpend response completed"); } @Override public void createShieldNullifier(GrpcAPI.NfParameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.createShieldNullifier request received"); try { BytesMessage nf = wallet .createShieldNullifier(request); responseObserver.onNext(nf); } catch (ZksnarkException e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.createShieldNullifier response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.createShieldNullifier response completed"); } @Override public void createSpendAuthSig(SpendAuthSigParameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.createSpendAuthSig request received"); try { BytesMessage spendAuthSig = wallet.createSpendAuthSig(request); responseObserver.onNext(spendAuthSig); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.createSpendAuthSig response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.createSpendAuthSig response completed"); } @Override public void getShieldTransactionHash(Transaction request, StreamObserver responseObserver) { + logger.debug("WalletApi.getShieldTransactionHash request received"); try { BytesMessage transactionHash = wallet.getShieldTransactionHash(request); responseObserver.onNext(transactionHash); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.getShieldTransactionHash response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getShieldTransactionHash response completed"); } @Override public void createShieldedContractParameters( PrivateShieldedTRC20Parameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.createShieldedContractParameters request received"); try { ShieldedTRC20Parameters shieldedTRC20Parameters = wallet .createShieldedContractParameters(request); @@ -2382,19 +2686,23 @@ public void createShieldedContractParameters( } catch (ZksnarkException | ContractValidateException | ContractExeException e) { responseObserver.onError(getRunTimeException(e)); logger.info("createShieldedContractParameters: {}", e.getMessage()); + logger.debug("WalletApi.createShieldedContractParameters response completed"); return; } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); logger.error("createShieldedContractParameters: ", e); + logger.debug("WalletApi.createShieldedContractParameters response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.createShieldedContractParameters response completed"); } @Override public void createShieldedContractParametersWithoutAsk( PrivateShieldedTRC20ParametersWithoutAsk request, StreamObserver responseObserver) { + logger.debug("WalletApi.createShieldedContractParametersWithoutAsk request received"); try { ShieldedTRC20Parameters shieldedTRC20Parameters = wallet .createShieldedContractParametersWithoutAsk(request); @@ -2403,15 +2711,18 @@ public void createShieldedContractParametersWithoutAsk( responseObserver.onError(getRunTimeException(e)); logger .info("createShieldedContractParametersWithoutAsk exception caught: " + e.getMessage()); + logger.debug("WalletApi.createShieldedContractParametersWithoutAsk response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.createShieldedContractParametersWithoutAsk response completed"); } @Override public void scanShieldedTRC20NotesByIvk( IvkDecryptTRC20Parameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.scanShieldedTRC20NotesByIvk request received"); long startNum = request.getStartBlockIndex(); long endNum = request.getEndBlockIndex(); try { @@ -2425,19 +2736,23 @@ public void scanShieldedTRC20NotesByIvk( } catch (BadItemException | ZksnarkException e) { responseObserver.onError(getRunTimeException(e)); logger.info("scanShieldedTRC20NotesByIvk: {}", e.getMessage()); + logger.debug("WalletApi.scanShieldedTRC20NotesByIvk response completed"); return; } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); logger.error("scanShieldedTRC20NotesByIvk:", e); + logger.debug("WalletApi.scanShieldedTRC20NotesByIvk response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.scanShieldedTRC20NotesByIvk response completed"); } @Override public void scanShieldedTRC20NotesByOvk( OvkDecryptTRC20Parameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.scanShieldedTRC20NotesByOvk request received"); long startNum = request.getStartBlockIndex(); long endNum = request.getEndBlockIndex(); try { @@ -2449,36 +2764,44 @@ public void scanShieldedTRC20NotesByOvk( } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); logger.info("scanShieldedTRC20NotesByOvk exception caught: " + e.getMessage()); + logger.debug("WalletApi.scanShieldedTRC20NotesByOvk response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.scanShieldedTRC20NotesByOvk response completed"); } @Override public void isShieldedTRC20ContractNoteSpent(NfTRC20Parameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.isShieldedTRC20ContractNoteSpent request received"); try { GrpcAPI.NullifierResult nf = wallet .isShieldedTRC20ContractNoteSpent(request); responseObserver.onNext(nf); } catch (Exception e) { responseObserver.onError(getRunTimeException(e)); + logger.debug("WalletApi.isShieldedTRC20ContractNoteSpent response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.isShieldedTRC20ContractNoteSpent response completed"); } @Override public void getTriggerInputForShieldedTRC20Contract( ShieldedTRC20TriggerContractParameters request, StreamObserver responseObserver) { + logger.debug("WalletApi.getTriggerInputForShieldedTRC20Contract request received"); try { responseObserver.onNext(wallet.getTriggerInputForShieldedTRC20Contract(request)); } catch (Exception e) { responseObserver.onError(e); + logger.debug("WalletApi.getTriggerInputForShieldedTRC20Contract response completed"); return; } responseObserver.onCompleted(); + logger.debug("WalletApi.getTriggerInputForShieldedTRC20Contract response completed"); } @Override @@ -2516,6 +2839,7 @@ public void createCommonTransaction(Transaction request, @Override public void getTransactionInfoByBlockNum(NumberMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getTransactionInfoByBlockNum request received"); try { responseObserver.onNext(wallet.getTransactionInfoByBlockNum(request.getNum())); } catch (Exception e) { @@ -2523,6 +2847,7 @@ public void getTransactionInfoByBlockNum(NumberMessage request, } responseObserver.onCompleted(); + logger.debug("WalletApi.getTransactionInfoByBlockNum response completed"); } @Override @@ -2541,6 +2866,7 @@ public void marketCancelOrder(MarketCancelOrderContract request, @Override public void getMarketOrderByAccount(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getMarketOrderByAccount request received"); try { ByteString address = request.getValue(); @@ -2551,11 +2877,13 @@ public void getMarketOrderByAccount(BytesMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getMarketOrderByAccount response completed"); } @Override public void getMarketOrderById(BytesMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getMarketOrderById request received"); try { ByteString address = request.getValue(); @@ -2566,11 +2894,13 @@ public void getMarketOrderById(BytesMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getMarketOrderById response completed"); } @Override public void getMarketPriceByPair(MarketOrderPair request, StreamObserver responseObserver) { + logger.debug("WalletApi.getMarketPriceByPair request received"); try { MarketPriceList marketPriceList = wallet .getMarketPriceByPair(request.getSellTokenId().toByteArray(), @@ -2580,11 +2910,13 @@ public void getMarketPriceByPair(MarketOrderPair request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getMarketPriceByPair response completed"); } @Override public void getMarketOrderListByPair(org.tron.protos.Protocol.MarketOrderPair request, StreamObserver responseObserver) { + logger.debug("WalletApi.getMarketOrderListByPair request received"); try { MarketOrderList orderPairList = wallet .getMarketOrderListByPair(request.getSellTokenId().toByteArray(), @@ -2594,11 +2926,13 @@ public void getMarketOrderListByPair(org.tron.protos.Protocol.MarketOrderPair re responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getMarketOrderListByPair response completed"); } @Override public void getMarketPairList(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("WalletApi.getMarketPairList request received"); try { MarketOrderPairList pairList = wallet.getMarketPairList(); responseObserver.onNext(pairList); @@ -2606,6 +2940,7 @@ public void getMarketPairList(EmptyMessage request, responseObserver.onError(getRunTimeException(e)); } responseObserver.onCompleted(); + logger.debug("WalletApi.getMarketPairList response completed"); } @Override @@ -2639,13 +2974,16 @@ public class MonitorApi extends MonitorGrpc.MonitorImplBase { @Override public void getStatsInfo(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("MonitorApi.getStatsInfo request received"); responseObserver.onNext(metricsApiService.getMetricProtoInfo()); responseObserver.onCompleted(); + logger.debug("MonitorApi.getStatsInfo response completed"); } } public void getRewardInfoCommon(BytesMessage request, StreamObserver responseObserver) { + logger.debug("getRewardInfo request received"); try { long value = dbManager.getMortgageService().queryReward(request.getValue().toByteArray()); NumberMessage.Builder builder = NumberMessage.newBuilder(); @@ -2655,10 +2993,12 @@ public void getRewardInfoCommon(BytesMessage request, responseObserver.onError(e); } responseObserver.onCompleted(); + logger.debug("getRewardInfo response completed"); } public void getBurnTrxCommon(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("getBurnTrx request received"); try { long value = dbManager.getDynamicPropertiesStore().getBurnTrxAmount(); NumberMessage.Builder builder = NumberMessage.newBuilder(); @@ -2668,10 +3008,12 @@ public void getBurnTrxCommon(EmptyMessage request, responseObserver.onError(e); } responseObserver.onCompleted(); + logger.debug("getBurnTrx response completed"); } public void getBrokerageInfoCommon(BytesMessage request, StreamObserver responseObserver) { + logger.debug("getBrokerageInfo request received"); try { long cycle = dbManager.getDynamicPropertiesStore().getCurrentCycleNumber(); long value = dbManager.getDelegationStore() @@ -2683,10 +3025,12 @@ public void getBrokerageInfoCommon(BytesMessage request, responseObserver.onError(e); } responseObserver.onCompleted(); + logger.debug("getBrokerageInfo response completed"); } public void getTransactionCountByBlockNumCommon(NumberMessage request, StreamObserver responseObserver) { + logger.debug("getTransactionCountByBlockNum request received: {}", request.getNum()); NumberMessage.Builder builder = NumberMessage.newBuilder(); try { Block block = chainBaseManager.getBlockByNum(request.getNum()).getInstance(); @@ -2697,10 +3041,12 @@ public void getTransactionCountByBlockNumCommon(NumberMessage request, } responseObserver.onNext(builder.build()); responseObserver.onCompleted(); + logger.debug("getTransactionCountByBlockNum response completed"); } public void getTransactionFromPendingCommon(BytesMessage request, StreamObserver responseObserver) { + logger.debug("getTransactionFromPending request received"); try { String txId = ByteArray.toHexString(request.getValue().toByteArray()); TransactionCapsule transactionCapsule = dbManager.getTxFromPending(txId); @@ -2709,10 +3055,12 @@ public void getTransactionFromPendingCommon(BytesMessage request, responseObserver.onError(e); } responseObserver.onCompleted(); + logger.debug("getTransactionFromPending response completed"); } public void getTransactionListFromPendingCommon(EmptyMessage request, StreamObserver responseObserver) { + logger.debug("getTransactionListFromPending request received"); try { TransactionIdList.Builder builder = TransactionIdList.newBuilder(); builder.addAllTxId(dbManager.getTxListFromPending()); @@ -2721,10 +3069,12 @@ public void getTransactionListFromPendingCommon(EmptyMessage request, responseObserver.onError(e); } responseObserver.onCompleted(); + logger.debug("getTransactionListFromPending response completed"); } public void getPendingSizeCommon(EmptyMessage request, StreamObserver responseObserver) { + logger.info("getPendingSize request received"); try { NumberMessage.Builder builder = NumberMessage.newBuilder(); builder.setNum(dbManager.getPendingSize()); @@ -2733,10 +3083,12 @@ public void getPendingSizeCommon(EmptyMessage request, responseObserver.onError(e); } responseObserver.onCompleted(); + logger.info("getPendingSize response completed"); } public void getBlockCommon(GrpcAPI.BlockReq request, StreamObserver responseObserver) { + logger.info("getBlock request received"); try { responseObserver.onNext(block2Extention(wallet.getBlock(request))); } catch (Exception e) { @@ -2748,6 +3100,7 @@ public void getBlockCommon(GrpcAPI.BlockReq request, } } responseObserver.onCompleted(); + logger.info("getBlock response completed"); } } diff --git a/framework/src/test/java/org/tron/common/utils/TypeConversionTest.java b/framework/src/test/java/org/tron/common/utils/TypeConversionTest.java index c98115af3f0..2dc536753ef 100644 --- a/framework/src/test/java/org/tron/common/utils/TypeConversionTest.java +++ b/framework/src/test/java/org/tron/common/utils/TypeConversionTest.java @@ -27,11 +27,30 @@ import static org.tron.common.utils.TypeConversion.longToBytes; import lombok.extern.slf4j.Slf4j; +import org.junit.After; +import org.junit.Before; +import org.junit.Rule; import org.junit.Test; +import org.junit.rules.TestName; -@Slf4j +@Slf4j(topic = "TypeConversionTest") public class TypeConversionTest { + @Rule + public TestName name = new TestName(); + + @Before + public void start() { + logger.debug("========== Starting test: {} ==========", name.getMethodName()); + System.out.println("========== Starting test: " + name.getMethodName() + " =========="); + } + + @After + public void end() throws InterruptedException { + logger.debug("========== Ending test: {} ==========", name.getMethodName()); + System.out.println("========== Ending test: " + name.getMethodName() + " =========="); + } + @Test public void testLongToBytes() { byte[] result = longToBytes(123L); diff --git a/framework/src/test/java/org/tron/core/exception/TronErrorTest.java b/framework/src/test/java/org/tron/core/exception/TronErrorTest.java index 53382ec265a..62b3e94fb21 100644 --- a/framework/src/test/java/org/tron/core/exception/TronErrorTest.java +++ b/framework/src/test/java/org/tron/core/exception/TronErrorTest.java @@ -8,6 +8,9 @@ import static org.mockito.Mockito.never; import static org.mockito.Mockito.times; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.util.ContextInitializer; +import ch.qos.logback.core.joran.spi.JoranException; import com.typesafe.config.Config; import com.typesafe.config.ConfigFactory; import com.typesafe.config.ConfigObject; @@ -37,6 +40,7 @@ import org.tron.core.services.http.GetBlockServlet; import org.tron.core.services.http.RateLimiterServlet; import org.tron.core.zen.ZksnarkInitService; +import org.slf4j.LoggerFactory; @RunWith(MockitoJUnitRunner.class) public class TronErrorTest { @@ -85,10 +89,22 @@ public void ZksnarkInitTest() throws IllegalAccessException, NoSuchFieldExceptio @Test public void LogLoadTest() throws IOException { - LogService.load("non-existent.xml"); - Path path = temporaryFolder.newFile("logback.xml").toPath(); - TronError thrown = assertThrows(TronError.class, () -> LogService.load(path.toString())); - assertEquals(TronError.ErrCode.LOG_LOAD, thrown.getErrCode()); + LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory(); + + try { + LogService.load("non-existent.xml"); + Path path = temporaryFolder.newFile("logback.xml").toPath(); + TronError thrown = assertThrows(TronError.class, () -> LogService.load(path.toString())); + assertEquals(TronError.ErrCode.LOG_LOAD, thrown.getErrCode()); + } finally { + try { + context.reset(); + ContextInitializer ci = new ContextInitializer(context); + ci.autoConfig(); + } catch (JoranException e) { + Assert.fail(e.getMessage()); + } + } } @Test diff --git a/framework/src/test/java/org/tron/core/services/ProposalServiceTest.java b/framework/src/test/java/org/tron/core/services/ProposalServiceTest.java index e81c75948b7..2d009b5ce37 100644 --- a/framework/src/test/java/org/tron/core/services/ProposalServiceTest.java +++ b/framework/src/test/java/org/tron/core/services/ProposalServiceTest.java @@ -10,10 +10,13 @@ import java.util.HashSet; import java.util.Set; import lombok.extern.slf4j.Slf4j; +import org.junit.After; import org.junit.Assert; import org.junit.Before; import org.junit.BeforeClass; +import org.junit.Rule; import org.junit.Test; +import org.junit.rules.TestName; import org.tron.common.BaseTest; import org.tron.common.parameter.CommonParameter; import org.tron.core.Constant; @@ -23,10 +26,11 @@ import org.tron.core.utils.ProposalUtil.ProposalType; import org.tron.protos.Protocol.Proposal; -@Slf4j +@Slf4j(topic = "ProposalServiceTest") public class ProposalServiceTest extends BaseTest { private static boolean init; + @Rule public TestName name = new TestName(); @BeforeClass public static void init() { @@ -35,7 +39,9 @@ public static void init() { } @Before - public void before() { + public void start() { + logger.debug("========== Starting test: {} ==========", name.getMethodName()); + System.out.println("========== Starting test: " + name.getMethodName() + " =========="); if (init) { return; } @@ -43,6 +49,12 @@ public void before() { init = true; } + @After + public void end() throws InterruptedException { + logger.debug("========== Ending test: {} ==========", name.getMethodName()); + System.out.println("========== Ending test: " + name.getMethodName() + " =========="); + } + @Test public void test() { Set set = new HashSet<>(); diff --git a/framework/src/test/java/org/tron/core/services/RpcApiServicesTest.java b/framework/src/test/java/org/tron/core/services/RpcApiServicesTest.java index dbd06fabffe..917620b8157 100644 --- a/framework/src/test/java/org/tron/core/services/RpcApiServicesTest.java +++ b/framework/src/test/java/org/tron/core/services/RpcApiServicesTest.java @@ -12,14 +12,18 @@ import java.io.IOException; import java.util.Objects; import java.util.concurrent.TimeUnit; +import lombok.extern.slf4j.Slf4j; +import org.junit.After; import org.junit.AfterClass; import org.junit.Assert; +import org.junit.Before; import org.junit.BeforeClass; import org.junit.ClassRule; import org.junit.FixMethodOrder; import org.junit.Rule; import org.junit.Test; import org.junit.rules.TemporaryFolder; +import org.junit.rules.TestName; import org.junit.rules.Timeout; import org.junit.runners.MethodSorters; import org.tron.api.DatabaseGrpc; @@ -54,6 +58,7 @@ import org.tron.common.application.ApplicationFactory; import org.tron.common.application.TronApplicationContext; import org.tron.common.utils.ByteArray; +import org.tron.common.utils.DebugInterceptor; import org.tron.common.utils.PublicMethod; import org.tron.common.utils.Sha256Hash; import org.tron.common.utils.TimeoutInterceptor; @@ -113,6 +118,7 @@ import org.tron.protos.contract.WitnessContract.WitnessUpdateContract; @FixMethodOrder(MethodSorters.NAME_ASCENDING) +@Slf4j(topic = "grpcTest") public class RpcApiServicesTest { private static Application appTest; @@ -128,8 +134,7 @@ public class RpcApiServicesTest { private static WalletSolidityBlockingStub blockingStubPBFT = null; @ClassRule public static TemporaryFolder temporaryFolder = new TemporaryFolder(); - @Rule - public Timeout timeout = new Timeout(30, TimeUnit.SECONDS); + @Rule public TestName name = new TestName(); private static ByteString ownerAddress; private static ByteString sk; private static ByteString ask; @@ -146,7 +151,7 @@ public static void init() throws IOException { Assert.assertEquals(5, getInstance().getRpcMaxRstStream()); Assert.assertEquals(10, getInstance().getRpcSecondsPerWindow()); String OWNER_ADDRESS = Wallet.getAddressPreFixString() - + "548794500882809695a8a687866e76d4271a1abc"; + + "0000000000000000000000000000000000000000"; getInstance().setRpcEnable(true); getInstance().setRpcPort(PublicMethod.chooseRandomPort()); getInstance().setRpcSolidityEnable(true); @@ -165,15 +170,15 @@ public static void init() throws IOException { channelFull = ManagedChannelBuilder.forTarget(fullNode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); channelPBFT = ManagedChannelBuilder.forTarget(pBFTNode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); channelSolidity = ManagedChannelBuilder.forTarget(solidityNode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); context = new TronApplicationContext(DefaultConfig.class); databaseBlockingStubFull = DatabaseGrpc.newBlockingStub(channelFull); @@ -210,6 +215,18 @@ public static void destroy() { Args.clearParam(); } + @Before + public void start() { + logger.debug("========== Starting test: {} ==========", name.getMethodName()); + System.out.println("========== Starting test: " + name.getMethodName() + " =========="); + } + + @After + public void end() throws InterruptedException { + logger.debug("========== Ending test: {} ==========", name.getMethodName()); + System.out.println("========== Ending test: " + name.getMethodName() + " =========="); + } + @Test public void testGetBlockByNum() { NumberMessage message = NumberMessage.newBuilder().setNum(0).build(); diff --git a/framework/src/test/java/org/tron/core/services/WalletApiTest.java b/framework/src/test/java/org/tron/core/services/WalletApiTest.java index f9c95f018c4..4e7e69d67ea 100644 --- a/framework/src/test/java/org/tron/core/services/WalletApiTest.java +++ b/framework/src/test/java/org/tron/core/services/WalletApiTest.java @@ -4,19 +4,23 @@ import java.io.IOException; import java.util.concurrent.TimeUnit; import lombok.extern.slf4j.Slf4j; +import org.junit.After; import org.junit.AfterClass; import org.junit.Assert; +import org.junit.Before; import org.junit.BeforeClass; import org.junit.ClassRule; import org.junit.Rule; import org.junit.Test; import org.junit.rules.TemporaryFolder; +import org.junit.rules.TestName; import org.junit.rules.Timeout; import org.tron.api.GrpcAPI.EmptyMessage; import org.tron.api.WalletGrpc; import org.tron.common.application.Application; import org.tron.common.application.ApplicationFactory; import org.tron.common.application.TronApplicationContext; +import org.tron.common.utils.DebugInterceptor; import org.tron.common.utils.PublicMethod; import org.tron.common.utils.TimeoutInterceptor; import org.tron.core.Constant; @@ -24,14 +28,12 @@ import org.tron.core.config.args.Args; -@Slf4j +@Slf4j(topic = "grpcTest") public class WalletApiTest { @ClassRule public static TemporaryFolder temporaryFolder = new TemporaryFolder(); - - @Rule - public Timeout timeout = new Timeout(30, TimeUnit.SECONDS); + @Rule public TestName name = new TestName(); private static TronApplicationContext context; private static Application appT; @@ -48,13 +50,25 @@ public static void init() throws IOException { appT.startup(); } + @Before + public void start() { + logger.debug("========== Starting test: {} ==========", name.getMethodName()); + System.out.println("========== Starting test: " + name.getMethodName() + " =========="); + } + + @After + public void end() throws InterruptedException { + logger.debug("========== Ending test: {} ==========", name.getMethodName()); + System.out.println("========== Ending test: " + name.getMethodName() + " =========="); + } + @Test public void listNodesTest() { String fullNode = String.format("%s:%d", "127.0.0.1", Args.getInstance().getRpcPort()); io.grpc.ManagedChannel channel = ManagedChannelBuilder.forTarget(fullNode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); try { WalletGrpc.WalletBlockingStub walletStub = WalletGrpc.newBlockingStub(channel); diff --git a/framework/src/test/java/org/tron/core/services/WitnessProductBlockServiceTest.java b/framework/src/test/java/org/tron/core/services/WitnessProductBlockServiceTest.java index 0b915b766b9..ae6e0ec5662 100644 --- a/framework/src/test/java/org/tron/core/services/WitnessProductBlockServiceTest.java +++ b/framework/src/test/java/org/tron/core/services/WitnessProductBlockServiceTest.java @@ -5,14 +5,35 @@ import java.util.Iterator; import java.util.Set; import java.util.concurrent.atomic.AtomicInteger; +import lombok.extern.slf4j.Slf4j; +import org.junit.After; import org.junit.Assert; +import org.junit.Before; +import org.junit.Rule; import org.junit.Test; +import org.junit.rules.TestName; import org.tron.common.utils.ByteArray; import org.tron.common.utils.Sha256Hash; import org.tron.core.capsule.BlockCapsule; +@Slf4j(topic = "WitnessProductBlockServiceTest") public class WitnessProductBlockServiceTest { + @Rule + public TestName name = new TestName(); + + @Before + public void start() { + logger.debug("========== Starting test: {} ==========", name.getMethodName()); + System.out.println("========== Starting test: " + name.getMethodName() + " =========="); + } + + @After + public void end() throws InterruptedException { + logger.debug("========== Ending test: {} ==========", name.getMethodName()); + System.out.println("========== Ending test: " + name.getMethodName() + " =========="); + } + @Test public void GetSetCheatWitnessInfoTest() { WitnessProductBlockService.CheatWitnessInfo cheatWitnessInfo = diff --git a/framework/src/test/java/org/tron/core/services/filter/LiteFnQueryGrpcInterceptorTest.java b/framework/src/test/java/org/tron/core/services/filter/LiteFnQueryGrpcInterceptorTest.java index b3cd5844b8d..1b66b62516f 100644 --- a/framework/src/test/java/org/tron/core/services/filter/LiteFnQueryGrpcInterceptorTest.java +++ b/framework/src/test/java/org/tron/core/services/filter/LiteFnQueryGrpcInterceptorTest.java @@ -6,14 +6,17 @@ import java.io.IOException; import java.util.concurrent.TimeUnit; import lombok.extern.slf4j.Slf4j; +import org.junit.After; import org.junit.AfterClass; import org.junit.Assert; +import org.junit.Before; import org.junit.BeforeClass; import org.junit.ClassRule; import org.junit.Rule; import org.junit.Test; import org.junit.rules.ExpectedException; import org.junit.rules.TemporaryFolder; +import org.junit.rules.TestName; import org.junit.rules.Timeout; import org.tron.api.GrpcAPI; import org.tron.api.WalletGrpc; @@ -21,6 +24,7 @@ import org.tron.common.application.Application; import org.tron.common.application.ApplicationFactory; import org.tron.common.application.TronApplicationContext; +import org.tron.common.utils.DebugInterceptor; import org.tron.common.utils.PublicMethod; import org.tron.common.utils.TimeoutInterceptor; import org.tron.core.ChainBaseManager; @@ -28,7 +32,7 @@ import org.tron.core.config.DefaultConfig; import org.tron.core.config.args.Args; -@Slf4j +@Slf4j(topic = "grpcTest") public class LiteFnQueryGrpcInterceptorTest { private static TronApplicationContext context; @@ -47,9 +51,7 @@ public class LiteFnQueryGrpcInterceptorTest { @ClassRule public static final TemporaryFolder temporaryFolder = new TemporaryFolder(); - - @Rule - public Timeout timeout = new Timeout(30, TimeUnit.SECONDS); + @Rule public TestName name = new TestName(); /** * init logic. @@ -72,15 +74,15 @@ public static void init() throws IOException { Args.getInstance().getRpcOnPBFTPort()); channelFull = ManagedChannelBuilder.forTarget(fullnode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); channelSolidity = ManagedChannelBuilder.forTarget(solidityNode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); channelpBFT = ManagedChannelBuilder.forTarget(pBFTNode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); context = new TronApplicationContext(DefaultConfig.class); blockingStubFull = WalletGrpc.newBlockingStub(channelFull); @@ -91,6 +93,18 @@ public static void init() throws IOException { appTest.startup(); } + @Before + public void start() { + logger.debug("========== Starting test: {} ==========", name.getMethodName()); + System.out.println("========== Starting test: " + name.getMethodName() + " =========="); + } + + @After + public void end() throws InterruptedException { + logger.debug("========== Ending test: {} ==========", name.getMethodName()); + System.out.println("========== Ending test: " + name.getMethodName() + " =========="); + } + /** * destroy the context. */ diff --git a/framework/src/test/java/org/tron/core/services/filter/RpcApiAccessInterceptorTest.java b/framework/src/test/java/org/tron/core/services/filter/RpcApiAccessInterceptorTest.java index 2e02125e014..02e33b75dd5 100644 --- a/framework/src/test/java/org/tron/core/services/filter/RpcApiAccessInterceptorTest.java +++ b/framework/src/test/java/org/tron/core/services/filter/RpcApiAccessInterceptorTest.java @@ -16,12 +16,15 @@ import java.util.Objects; import java.util.concurrent.TimeUnit; import lombok.extern.slf4j.Slf4j; +import org.junit.After; import org.junit.AfterClass; +import org.junit.Before; import org.junit.BeforeClass; import org.junit.ClassRule; import org.junit.Rule; import org.junit.Test; import org.junit.rules.TemporaryFolder; +import org.junit.rules.TestName; import org.junit.rules.Timeout; import org.tron.api.GrpcAPI.BlockExtention; import org.tron.api.GrpcAPI.BlockReq; @@ -34,6 +37,7 @@ import org.tron.common.application.Application; import org.tron.common.application.ApplicationFactory; import org.tron.common.application.TronApplicationContext; +import org.tron.common.utils.DebugInterceptor; import org.tron.common.utils.PublicMethod; import org.tron.common.utils.TimeoutInterceptor; import org.tron.core.Constant; @@ -42,7 +46,7 @@ import org.tron.core.services.RpcApiService; import org.tron.protos.Protocol.Transaction; -@Slf4j +@Slf4j(topic = "grpcTest") public class RpcApiAccessInterceptorTest { private static TronApplicationContext context; @@ -54,10 +58,7 @@ public class RpcApiAccessInterceptorTest { private static WalletSolidityGrpc.WalletSolidityBlockingStub blockingStubPBFT = null; @ClassRule public static final TemporaryFolder temporaryFolder = new TemporaryFolder(); - - @Rule - public Timeout timeout = new Timeout(30, TimeUnit.SECONDS); - + @Rule public TestName name = new TestName(); /** * init logic. */ @@ -80,15 +81,15 @@ public static void init() throws IOException { channelFull = ManagedChannelBuilder.forTarget(fullNode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); channelPBFT = ManagedChannelBuilder.forTarget(pBFTNode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); channelSolidity = ManagedChannelBuilder.forTarget(solidityNode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); context = new TronApplicationContext(DefaultConfig.class); @@ -101,6 +102,18 @@ public static void init() throws IOException { appTest.startup(); } + @Before + public void start() { + logger.debug("========== Starting test: {} ==========", name.getMethodName()); + System.out.println("========== Starting test: " + name.getMethodName() + " =========="); + } + + @After + public void end() throws InterruptedException { + logger.debug("========== Ending test: {} ==========", name.getMethodName()); + System.out.println("========== Ending test: " + name.getMethodName() + " =========="); + } + /** * destroy the context. */ diff --git a/framework/src/test/java/org/tron/program/SolidityNodeTest.java b/framework/src/test/java/org/tron/program/SolidityNodeTest.java index 943c73cb9ed..8841098f5d5 100755 --- a/framework/src/test/java/org/tron/program/SolidityNodeTest.java +++ b/framework/src/test/java/org/tron/program/SolidityNodeTest.java @@ -6,9 +6,12 @@ import java.util.concurrent.TimeUnit; import javax.annotation.Resource; import lombok.extern.slf4j.Slf4j; +import org.junit.After; import org.junit.Assert; +import org.junit.Before; import org.junit.Rule; import org.junit.Test; +import org.junit.rules.TestName; import org.junit.rules.Timeout; import org.tron.common.BaseTest; import org.tron.common.client.DatabaseGrpcClient; @@ -21,7 +24,7 @@ import org.tron.protos.Protocol.Block; import org.tron.protos.Protocol.DynamicProperties; -@Slf4j +@Slf4j(topic = "grpcTest") public class SolidityNodeTest extends BaseTest { @Resource @@ -31,8 +34,20 @@ public class SolidityNodeTest extends BaseTest { static int rpcPort = PublicMethod.chooseRandomPort(); static int solidityHttpPort = PublicMethod.chooseRandomPort(); - @Rule - public Timeout timeout = new Timeout(30, TimeUnit.SECONDS); + @Rule public TestName name = new TestName(); + + + @Before + public void start() { + logger.debug("========== Starting test: {} ==========", name.getMethodName()); + System.out.println("========== Starting test: " + name.getMethodName() + " =========="); + } + + @After + public void end() throws InterruptedException { + logger.debug("========== Ending test: {} ==========", name.getMethodName()); + System.out.println("========== Ending test: " + name.getMethodName() + " =========="); + } static { Args.setParam(new String[] {"-d", dbPath(), "--solidity"}, Constant.TEST_CONF); diff --git a/framework/src/test/resources/logback-test.xml b/framework/src/test/resources/logback-test.xml index 9cf4a04062f..6f0383cacc0 100644 --- a/framework/src/test/resources/logback-test.xml +++ b/framework/src/test/resources/logback-test.xml @@ -4,10 +4,10 @@ - %d{HH:mm:ss.SSS} %p [%c{1}] %m%n + %d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%t] [%c{1}]\(%F:%L\) %m%n - INFO + ERROR @@ -25,7 +25,15 @@ 20GB - %d{HH:mm:ss.SSS} %p [%c{1}] %m%n + %d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%t] [%c{1}]\(%F:%L\) %m%n + + + + + ./logs/net.log + true + + %d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%t] [%c{1}]\(%F:%L\) %m%n @@ -34,7 +42,44 @@ - - + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/gradle/verification-metadata.xml b/gradle/verification-metadata.xml index 8be6c6626f4..7bc5bbe8460 100644 --- a/gradle/verification-metadata.xml +++ b/gradle/verification-metadata.xml @@ -2190,30 +2190,20 @@ - - - + + + - - + + - - - + + + - - - - - - - - - - - - + + @@ -2224,21 +2214,6 @@ - - - - - - - - - - - - - - - diff --git a/plugins/build.gradle b/plugins/build.gradle index e03e9a7c49a..15fb1aee8e8 100644 --- a/plugins/build.gradle +++ b/plugins/build.gradle @@ -95,16 +95,15 @@ test { classDumpDir = file("$buildDir/jacoco/classpathdumps") } - if (rootProject.archInfo.isArm64) { - exclude 'org/tron/plugins/leveldb/**' - filter { - excludeTestsMatching '*.*leveldb*' - excludeTestsMatching '*.*Leveldb*' - excludeTestsMatching '*.*LevelDB*' - excludeTestsMatching '*.*LevelDb*' - excludeTestsMatching '*.*Archive*' - } + exclude 'org/tron/plugins/leveldb/**' + filter { + excludeTestsMatching '*.*leveldb*' + excludeTestsMatching '*.*Leveldb*' + excludeTestsMatching '*.*LevelDB*' + excludeTestsMatching '*.*LevelDb*' + excludeTestsMatching '*.*Archive*' } + } jacocoTestReport { diff --git a/plugins/src/test/java/org/tron/plugins/DbLiteTest.java b/plugins/src/test/java/org/tron/plugins/DbLiteTest.java index 80fd90cce81..0c019901799 100644 --- a/plugins/src/test/java/org/tron/plugins/DbLiteTest.java +++ b/plugins/src/test/java/org/tron/plugins/DbLiteTest.java @@ -17,6 +17,7 @@ import org.tron.common.application.TronApplicationContext; import org.tron.common.config.DbBackupConfig; import org.tron.common.crypto.ECKey; +import org.tron.common.utils.DebugInterceptor; import org.tron.common.utils.FileUtil; import org.tron.common.utils.PublicMethod; import org.tron.common.utils.TimeoutInterceptor; @@ -52,7 +53,7 @@ public void startApp() { Args.getInstance().getRpcPort()); channelFull = ManagedChannelBuilder.forTarget(fullNode) .usePlaintext() - .intercept(new TimeoutInterceptor(5000)) + .intercept(new TimeoutInterceptor(5000), new DebugInterceptor()) .build(); blockingStubFull = WalletGrpc.newBlockingStub(channelFull); }