services: binlog status code, msg, details (#4551)

Log these additional bits of info in RPC binary logging

services/src/main/java/io/grpc/services/BinlogHelper.java

@@ -83,6 +83,14 @@ final class BinlogHelper {
   private static final Logger logger = Logger.getLogger(BinlogHelper.class.getName());
   private static final boolean SERVER = true;
   private static final boolean CLIENT = false;
+  // Normally 'grpc-' metadata keys are set from within gRPC, and applications are not allowed
+  // to set them. This key is a special well known key that set from the application layer, but
+  // represents a com.google.rpc.Status and is given special first class treatment.
+  // See StatusProto.java
+  static final Metadata.Key<byte[]> STATUS_DETAILS_KEY =
+      Metadata.Key.of(
+          "grpc-status-details-bin",
+          Metadata.BINARY_BYTE_MARSHALLER);
 
   @VisibleForTesting
   static final SocketAddress DUMMY_SOCKET = new DummySocketAddress();
@@ -168,12 +176,23 @@ final class BinlogHelper {
     }
 
     @Override
-    void logTrailingMetadata(int seq, Metadata metadata, boolean isServer, CallId callId) {
+    void logTrailingMetadata(
+        int seq, Status status, Metadata metadata, boolean isServer, CallId callId) {
       GrpcLogEntry.Builder entryBuilder = GrpcLogEntry.newBuilder()
           .setSequenceIdWithinCall(seq)
           .setType(isServer ? Type.SEND_TRAILING_METADATA : Type.RECV_TRAILING_METADATA)
           .setLogger(isServer ? GrpcLogEntry.Logger.SERVER : GrpcLogEntry.Logger.CLIENT)
-          .setCallId(callIdToProto(callId));
+          .setCallId(callIdToProto(callId))
+          .setStatusCode(status.getCode().value());
+      String statusDescription = status.getDescription();
+      if (statusDescription != null) {
+        entryBuilder.setStatusMessage(statusDescription);
+      }
+      byte[] statusDetailBytes = metadata.get(STATUS_DETAILS_KEY);
+      if (statusDetailBytes != null) {
+        entryBuilder.setStatusDetails(ByteString.copyFrom(statusDetailBytes));
+      }
+
       addMetadataToProto(entryBuilder, metadata, maxHeaderBytes);
       sink.write(entryBuilder.build());
     }
@@ -260,7 +279,8 @@ final class BinlogHelper {
      * Logs the trailing metadata. This method logs the appropriate number of bytes
      * as determined by the binary logging configuration.
      */
-    abstract void logTrailingMetadata(int seq, Metadata metadata, boolean isServer, CallId callId);
+    abstract void logTrailingMetadata(
+        int seq, Status status, Metadata metadata, boolean isServer, CallId callId);
 
     /**
      * Logs the outbound message. This method logs the appropriate number of bytes from
@@ -359,7 +379,8 @@ final class BinlogHelper {
 
                   @Override
                   public void onClose(Status status, Metadata trailers) {
-                    writer.logTrailingMetadata(seq.getAndIncrement(), trailers, CLIENT, callId);
+                    writer.logTrailingMetadata(
+                        seq.getAndIncrement(), status, trailers, CLIENT, callId);
                     super.onClose(status, trailers);
                   }
                 };
@@ -425,7 +446,7 @@ final class BinlogHelper {
 
           @Override
           public void close(Status status, Metadata trailers) {
-            writer.logTrailingMetadata(seq.getAndIncrement(), trailers, SERVER, callId);
+            writer.logTrailingMetadata(seq.getAndIncrement(), status, trailers, SERVER, callId);
             super.close(status, trailers);
           }
         };

services/src/test/java/io/grpc/services/BinlogHelperTest.java

@@ -19,6 +19,7 @@ package io.grpc.services;
 import static com.google.common.truth.Truth.assertThat;
 import static io.grpc.services.BinaryLogProvider.BYTEARRAY_MARSHALLER;
 import static io.grpc.services.BinlogHelper.DUMMY_SOCKET;
+import static io.grpc.services.BinlogHelper.STATUS_DETAILS_KEY;
 import static io.grpc.services.BinlogHelper.getPeerSocket;
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertNotNull;
@@ -667,7 +668,7 @@ public final class BinlogHelperTest {
 
   @Test
   public void logTrailingMetadata_server() throws Exception {
-    sinkWriterImpl.logTrailingMetadata(/*seq=*/ 1, nonEmptyMetadata, IS_SERVER, CALL_ID);
+    sinkWriterImpl.logTrailingMetadata(/*seq=*/ 1, Status.OK, nonEmptyMetadata, IS_SERVER, CALL_ID);
     verify(sink).write(
         metadataToProtoTestHelper(nonEmptyMetadata, 10).toBuilder()
             .setSequenceIdWithinCall(1)
@@ -675,11 +676,32 @@ public final class BinlogHelperTest {
             .setLogger(GrpcLogEntry.Logger.SERVER)
             .setCallId(BinlogHelper.callIdToProto(CALL_ID))
             .build());
+
+    Metadata detailedStatus = new Metadata();
+    byte[] statusBytes = new byte[] {1, 2, 3, 4};
+    detailedStatus.merge(nonEmptyMetadata);
+    detailedStatus.put(STATUS_DETAILS_KEY, statusBytes);
+    sinkWriterImpl.logTrailingMetadata(
+        /*seq=*/ 1,
+        Status.INTERNAL.withDescription("description"),
+        detailedStatus,
+        IS_SERVER,
+        CALL_ID);
+    verify(sink).write(
+        metadataToProtoTestHelper(detailedStatus, 10).toBuilder()
+            .setSequenceIdWithinCall(1)
+            .setType(GrpcLogEntry.Type.SEND_TRAILING_METADATA)
+            .setLogger(GrpcLogEntry.Logger.SERVER)
+            .setCallId(BinlogHelper.callIdToProto(CALL_ID))
+            .setStatusCode(13)
+            .setStatusMessage("description")
+            .setStatusDetails(ByteString.copyFrom(statusBytes))
+            .build());
   }
 
   @Test
   public void logTrailingMetadata_client() throws Exception {
-    sinkWriterImpl.logTrailingMetadata(/*seq=*/ 1, nonEmptyMetadata, IS_CLIENT, CALL_ID);
+    sinkWriterImpl.logTrailingMetadata(/*seq=*/ 1, Status.OK, nonEmptyMetadata, IS_CLIENT, CALL_ID);
     verify(sink).write(
         metadataToProtoTestHelper(nonEmptyMetadata, 10).toBuilder()
             .setSequenceIdWithinCall(1)
@@ -687,6 +709,28 @@ public final class BinlogHelperTest {
             .setLogger(GrpcLogEntry.Logger.CLIENT)
             .setCallId(BinlogHelper.callIdToProto(CALL_ID))
             .build());
+
+    Metadata detailedStatus = new Metadata();
+    byte[] statusBytes = new byte[] {1, 2, 3, 4};
+    detailedStatus.merge(nonEmptyMetadata);
+    detailedStatus.put(STATUS_DETAILS_KEY, statusBytes);
+    sinkWriterImpl.logTrailingMetadata(
+        /*seq=*/ 1,
+        Status.INTERNAL.withDescription("description"),
+        detailedStatus,
+        IS_CLIENT,
+        CALL_ID);
+    verify(sink).write(
+        metadataToProtoTestHelper(detailedStatus, 10).toBuilder()
+            .setSequenceIdWithinCall(1)
+            .setType(GrpcLogEntry.Type.RECV_TRAILING_METADATA)
+            .setLogger(GrpcLogEntry.Logger.CLIENT)
+            .setCallId(BinlogHelper.callIdToProto(CALL_ID))
+            .setStatusCode(13)
+            .setStatusMessage("description")
+            .setStatusDetails(ByteString.copyFrom(statusBytes))
+            .build());
+
   }
 
   @Test
@@ -1022,6 +1066,7 @@ public final class BinlogHelperTest {
       interceptedListener.get().onClose(status, trailers);
       verify(mockSinkWriter).logTrailingMetadata(
           /*seq=*/ eq(5),
+          same(status),
           same(trailers),
           eq(IS_CLIENT),
           same(CALL_ID));
@@ -1161,6 +1206,7 @@ public final class BinlogHelperTest {
       interceptedCall.get().close(status, trailers);
       verify(mockSinkWriter).logTrailingMetadata(
           /*seq=*/ eq(5),
+          same(status),
           same(trailers),
           eq(IS_SERVER),
           same(CALL_ID));