This change adds timestamps (call start and end time) to the remote grpc log.

PiperOrigin-RevId: 193937177

3 files changed, 21 insertions, 3 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java b/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java
index 2a34533bfc..d9ab87a9f1 100644
--- a/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java
+++ b/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java
@@ -133,7 +133,7 @@ public final class RemoteModule extends BlazeModule {
       LoggingInterceptor logger = null;
       if (!remoteOptions.experimentalRemoteGrpcLog.isEmpty()) {
         rpcLogFile = new AsynchronousFileOutputStream(remoteOptions.experimentalRemoteGrpcLog);
-        logger = new LoggingInterceptor(rpcLogFile);
+        logger = new LoggingInterceptor(rpcLogFile, env.getRuntime().getClock());
       }
 
       RemoteRetrier retrier =
diff --git a/src/main/java/com/google/devtools/build/lib/remote/logging/BUILD b/src/main/java/com/google/devtools/build/lib/remote/logging/BUILD
index dc1caa6266..0a1d806595 100644
--- a/src/main/java/com/google/devtools/build/lib/remote/logging/BUILD
+++ b/src/main/java/com/google/devtools/build/lib/remote/logging/BUILD
@@ -12,10 +12,12 @@ java_library(
     tags = ["bazel"],
     deps = [
         "//src/main/java/com/google/devtools/build/lib:io",
+        "//src/main/java/com/google/devtools/build/lib/clock",
         "//src/main/java/com/google/devtools/build/lib/remote/util",
         "//src/main/protobuf:remote_execution_log_java_proto",
         "//third_party:guava",
         "//third_party/grpc:grpc-jar",
+        "//third_party/protobuf:protobuf_java",
         "@googleapis//:google_bytestream_bytestream_java_grpc",
         "@googleapis//:google_bytestream_bytestream_java_proto",
         "@googleapis//:google_devtools_remoteexecution_v1test_remote_execution_java_grpc",
diff --git a/src/main/java/com/google/devtools/build/lib/remote/logging/LoggingInterceptor.java b/src/main/java/com/google/devtools/build/lib/remote/logging/LoggingInterceptor.java
index a805eae83b..bf1b393ecb 100644
--- a/src/main/java/com/google/devtools/build/lib/remote/logging/LoggingInterceptor.java
+++ b/src/main/java/com/google/devtools/build/lib/remote/logging/LoggingInterceptor.java
@@ -15,6 +15,7 @@
 package com.google.devtools.build.lib.remote.logging;
 
 import com.google.bytestream.ByteStreamGrpc;
+import com.google.devtools.build.lib.clock.Clock;
 import com.google.devtools.build.lib.remote.logging.RemoteExecutionLog.LogEntry;
 import com.google.devtools.build.lib.remote.util.TracingMetadataUtils;
 import com.google.devtools.build.lib.util.io.AsynchronousFileOutputStream;
@@ -22,6 +23,7 @@ import com.google.devtools.remoteexecution.v1test.ActionCacheGrpc;
 import com.google.devtools.remoteexecution.v1test.ContentAddressableStorageGrpc;
 import com.google.devtools.remoteexecution.v1test.ExecutionGrpc;
 import com.google.devtools.remoteexecution.v1test.RequestMetadata;
+import com.google.protobuf.Timestamp;
 import com.google.watcher.v1.WatcherGrpc;
 import io.grpc.CallOptions;
 import io.grpc.Channel;
@@ -32,15 +34,18 @@ import io.grpc.ForwardingClientCallListener;
 import io.grpc.Metadata;
 import io.grpc.MethodDescriptor;
 import io.grpc.Status;
+import java.time.Instant;
 import javax.annotation.Nullable;
 
 /** Client interceptor for logging details of certain gRPC calls. */
 public class LoggingInterceptor implements ClientInterceptor {
-  AsynchronousFileOutputStream rpcLogFile;
+  private final AsynchronousFileOutputStream rpcLogFile;
+  private final Clock clock;
 
   /** Constructs a LoggingInterceptor which logs RPC calls to the given file. */
-  public LoggingInterceptor(AsynchronousFileOutputStream rpcLogFile) {
+  public LoggingInterceptor(AsynchronousFileOutputStream rpcLogFile, Clock clock) {
     this.rpcLogFile = rpcLogFile;
+    this.clock = clock;
   }
 
   /**
@@ -80,6 +85,15 @@ public class LoggingInterceptor implements ClientInterceptor {
     }
   }
 
+  /** Get current time as a Timestamp. */
+  private Timestamp getCurrentTimestamp() {
+    Instant time = Instant.ofEpochMilli(clock.currentTimeMillis());
+    return Timestamp.newBuilder()
+        .setSeconds(time.getEpochSecond())
+        .setNanos(time.getNano())
+        .build();
+  }
+
   /**
    * Wraps client call to log call details by building a {@link LogEntry} and writing it to the RPC
    * log file.
@@ -100,6 +114,7 @@ public class LoggingInterceptor implements ClientInterceptor {
 
     @Override
     public void start(Listener<RespT> responseListener, Metadata headers) {
+      entryBuilder.setStartTime(getCurrentTimestamp());
       RequestMetadata metadata = TracingMetadataUtils.requestMetadataFromHeaders(headers);
       if (metadata != null) {
         entryBuilder.setMetadata(metadata);
@@ -115,6 +130,7 @@ public class LoggingInterceptor implements ClientInterceptor {
 
             @Override
             public void onClose(Status status, Metadata trailers) {
+              entryBuilder.setEndTime(getCurrentTimestamp());
               entryBuilder.setStatus(makeStatusProto(status));
               entryBuilder.setDetails(handler.getDetails());
               rpcLogFile.write(entryBuilder.build());