diff --git a/alts/src/main/java/io/grpc/alts/internal/AltsProtocolNegotiator.java b/alts/src/main/java/io/grpc/alts/internal/AltsProtocolNegotiator.java index 300fd78899..bebf968eac 100644 --- a/alts/src/main/java/io/grpc/alts/internal/AltsProtocolNegotiator.java +++ b/alts/src/main/java/io/grpc/alts/internal/AltsProtocolNegotiator.java @@ -34,6 +34,8 @@ import io.grpc.netty.ProtocolNegotiators.AbstractBufferingHandler; import io.netty.channel.ChannelHandler; import io.netty.channel.ChannelHandlerContext; import io.netty.util.AsciiString; +import java.util.logging.Level; +import java.util.logging.Logger; /** * A GRPC {@link ProtocolNegotiator} for ALTS. This class creates a Netty handler that provides ALTS @@ -41,6 +43,8 @@ import io.netty.util.AsciiString; */ public abstract class AltsProtocolNegotiator implements ProtocolNegotiator { + private static final Logger logger = Logger.getLogger(AltsProtocolNegotiator.class.getName()); + @Grpc.TransportAttr public static final Attributes.Key TSI_PEER_KEY = Attributes.Key.create("TSI_PEER"); @Grpc.TransportAttr @@ -51,46 +55,52 @@ public abstract class AltsProtocolNegotiator implements ProtocolNegotiator { /** Creates a negotiator used for ALTS client. */ public static AltsProtocolNegotiator createClientNegotiator( final TsiHandshakerFactory handshakerFactory) { - return new AltsProtocolNegotiator() { + final class ClientAltsProtocolNegotiator extends AltsProtocolNegotiator { @Override public Handler newHandler(GrpcHttp2ConnectionHandler grpcHandler) { + TsiHandshaker handshaker = handshakerFactory.newHandshaker(grpcHandler.getAuthority()); return new BufferUntilAltsNegotiatedHandler( grpcHandler, - new TsiHandshakeHandler( - new NettyTsiHandshaker( - handshakerFactory.newHandshaker(grpcHandler.getAuthority()))), + new TsiHandshakeHandler(new NettyTsiHandshaker(handshaker)), new TsiFrameHandler()); } @Override public void close() { + logger.finest("ALTS Client ProtocolNegotiator Closed"); // TODO(jiangtaoli2016): release resources } - }; + } + + return new ClientAltsProtocolNegotiator(); } /** Creates a negotiator used for ALTS server. */ public static AltsProtocolNegotiator createServerNegotiator( final TsiHandshakerFactory handshakerFactory) { - return new AltsProtocolNegotiator() { + final class ServerAltsProtocolNegotiator extends AltsProtocolNegotiator { @Override public Handler newHandler(GrpcHttp2ConnectionHandler grpcHandler) { + TsiHandshaker handshaker = handshakerFactory.newHandshaker(/*authority=*/ null); return new BufferUntilAltsNegotiatedHandler( grpcHandler, - new TsiHandshakeHandler(new NettyTsiHandshaker(handshakerFactory.newHandshaker(null))), + new TsiHandshakeHandler(new NettyTsiHandshaker(handshaker)), new TsiFrameHandler()); } @Override public void close() { + logger.finest("ALTS Server ProtocolNegotiator Closed"); // TODO(jiangtaoli2016): release resources } - }; + } + + return new ServerAltsProtocolNegotiator(); } /** Buffers all writes until the ALTS handshake is complete. */ @VisibleForTesting - static class BufferUntilAltsNegotiatedHandler extends AbstractBufferingHandler + static final class BufferUntilAltsNegotiatedHandler extends AbstractBufferingHandler implements ProtocolNegotiator.Handler { private final GrpcHttp2ConnectionHandler grpcHandler; @@ -105,7 +115,8 @@ public abstract class AltsProtocolNegotiator implements ProtocolNegotiator { // TODO: Remove this once https://github.com/grpc/grpc-java/pull/3715 is in. @Override - public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) throws Exception { + public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) { + logger.log(Level.FINEST, "Exception while buffering for ALTS Negotiation", cause); fail(ctx, cause); ctx.fireExceptionCaught(cause); } @@ -117,6 +128,9 @@ public abstract class AltsProtocolNegotiator implements ProtocolNegotiator { @Override public void userEventTriggered(ChannelHandlerContext ctx, Object evt) throws Exception { + if (logger.isLoggable(Level.FINEST)) { + logger.log(Level.FINEST, "User Event triggered while negotiating ALTS", new Object[]{evt}); + } if (evt instanceof TsiHandshakeCompletionEvent) { TsiHandshakeCompletionEvent altsEvt = (TsiHandshakeCompletionEvent) evt; if (altsEvt.isSuccess()) { @@ -138,6 +152,7 @@ public abstract class AltsProtocolNegotiator implements ProtocolNegotiator { + RpcProtocolVersionsUtil.getRpcProtocolVersions().toString() + "are not compatible with peer Rpc Protocol Versions " + altsContext.getPeerRpcVersions().toString(); + logger.finest(errorMessage); fail(ctx, Status.UNAVAILABLE.withDescription(errorMessage).asRuntimeException()); } grpcHandler.handleProtocolNegotiationCompleted( @@ -150,10 +165,11 @@ public abstract class AltsProtocolNegotiator implements ProtocolNegotiator { .build(), new Security(new OtherSecurity("alts", Any.pack(altsContext.context)))); } - + logger.finest("Flushing ALTS buffered data"); // Now write any buffered data and remove this handler. writeBufferedAndRemove(ctx); } else { + logger.log(Level.FINEST, "ALTS handshake failed", altsEvt.cause()); fail(ctx, unavailableException("ALTS handshake failed", altsEvt.cause())); } } diff --git a/alts/src/main/java/io/grpc/alts/internal/TsiFrameHandler.java b/alts/src/main/java/io/grpc/alts/internal/TsiFrameHandler.java index a7afca218c..a2c1a1d7c6 100644 --- a/alts/src/main/java/io/grpc/alts/internal/TsiFrameHandler.java +++ b/alts/src/main/java/io/grpc/alts/internal/TsiFrameHandler.java @@ -34,6 +34,8 @@ import java.security.GeneralSecurityException; import java.util.ArrayList; import java.util.List; import java.util.concurrent.Future; +import java.util.logging.Level; +import java.util.logging.Logger; /** * Encrypts and decrypts TSI Frames. Writes are buffered here until {@link #flush} is called. Writes @@ -41,6 +43,8 @@ import java.util.concurrent.Future; */ public final class TsiFrameHandler extends ByteToMessageDecoder implements ChannelOutboundHandler { + private static final Logger logger = Logger.getLogger(TsiFrameHandler.class.getName()); + private TsiFrameProtector protector; private PendingWriteQueue pendingUnprotectedWrites; @@ -48,6 +52,7 @@ public final class TsiFrameHandler extends ByteToMessageDecoder implements Chann @Override public void handlerAdded(ChannelHandlerContext ctx) throws Exception { + logger.finest("TsiFrameHandler added"); super.handlerAdded(ctx); assert pendingUnprotectedWrites == null; pendingUnprotectedWrites = new PendingWriteQueue(checkNotNull(ctx)); @@ -55,6 +60,9 @@ public final class TsiFrameHandler extends ByteToMessageDecoder implements Chann @Override public void userEventTriggered(ChannelHandlerContext ctx, Object event) throws Exception { + if (logger.isLoggable(Level.FINEST)) { + logger.log(Level.FINEST, "TsiFrameHandler user event triggered", new Object[]{event}); + } if (event instanceof TsiHandshakeCompletionEvent) { TsiHandshakeCompletionEvent tsiEvent = (TsiHandshakeCompletionEvent) event; if (tsiEvent.isSuccess()) { @@ -68,6 +76,7 @@ public final class TsiFrameHandler extends ByteToMessageDecoder implements Chann @VisibleForTesting void setProtector(TsiFrameProtector protector) { + logger.finest("TsiFrameHandler protector set"); checkState(this.protector == null); this.protector = checkNotNull(protector); } @@ -95,7 +104,8 @@ public final class TsiFrameHandler extends ByteToMessageDecoder implements Chann } @Override - public void handlerRemoved0(ChannelHandlerContext ctx) throws Exception { + public void handlerRemoved0(ChannelHandlerContext ctx) { + logger.finest("TsiFrameHandler removed"); if (!pendingUnprotectedWrites.isEmpty()) { pendingUnprotectedWrites.removeAndFailAll( new ChannelException("Pending write on removal of TSI handler")); diff --git a/alts/src/main/java/io/grpc/alts/internal/TsiHandshakeHandler.java b/alts/src/main/java/io/grpc/alts/internal/TsiHandshakeHandler.java index 98c9a7ddfb..98dd1f9090 100644 --- a/alts/src/main/java/io/grpc/alts/internal/TsiHandshakeHandler.java +++ b/alts/src/main/java/io/grpc/alts/internal/TsiHandshakeHandler.java @@ -19,6 +19,7 @@ package io.grpc.alts.internal; import static com.google.common.base.Preconditions.checkNotNull; import com.google.common.annotations.VisibleForTesting; +import com.google.common.base.MoreObjects; import io.netty.buffer.ByteBuf; import io.netty.buffer.ByteBufAllocator; import io.netty.channel.ChannelHandlerContext; @@ -27,6 +28,8 @@ import io.netty.util.ReferenceCountUtil; import java.security.GeneralSecurityException; import java.util.List; import java.util.concurrent.Future; +import java.util.logging.Level; +import java.util.logging.Logger; import javax.annotation.Nullable; /** @@ -34,6 +37,9 @@ import javax.annotation.Nullable; * TsiHandshakeCompletionEvent} indicating the result of the handshake. */ public final class TsiHandshakeHandler extends ByteToMessageDecoder { + + private static final Logger logger = Logger.getLogger(TsiHandshakeHandler.class.getName()); + private static final int HANDSHAKE_FRAME_SIZE = 1024; private final NettyTsiHandshaker handshaker; @@ -106,28 +112,42 @@ public final class TsiHandshakeHandler extends ByteToMessageDecoder { TsiFrameProtector protector() { return protector; } + + @Override + public String toString() { + return MoreObjects.toStringHelper(this) + .add("peer", peer) + .add("protector", protector) + .add("context", context) + .add("cause", cause) + .toString(); + } } @Override public void handlerAdded(ChannelHandlerContext ctx) throws Exception { + logger.finest("TsiHandshakeHandler added"); maybeStart(ctx); super.handlerAdded(ctx); } @Override public void channelActive(ChannelHandlerContext ctx) throws Exception { + logger.finest("TsiHandshakeHandler channel active"); maybeStart(ctx); super.channelActive(ctx); } @Override public void handlerRemoved0(ChannelHandlerContext ctx) throws Exception { + logger.finest("TsiHandshakeHandler handler removed"); close(); super.handlerRemoved0(ctx); } @Override public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) throws Exception { + logger.log(Level.FINEST, "Exception in TsiHandshakeHandler", cause); ctx.fireUserEventTriggered(new TsiHandshakeCompletionEvent(cause)); super.exceptionCaught(ctx, cause); }