pw_rpc: Expand debug logs for pw_rpc activity

Add descriptive logs for each phase of an RPC call.

Change-Id: I2ff5f4c833c9045dc97524635cc3d571f6262b34
Reviewed-on: https://pigweed-review.googlesource.com/c/pigweed/pigweed/+/89700
Reviewed-by: Ted Pudlik <tpudlik@google.com>
Pigweed-Auto-Submit: Wyatt Hepler <hepler@google.com>
Reviewed-by: Anthony DiGirolamo <tonymd@google.com>
Reviewed-by: Armando Montanez <amontanez@google.com>
Commit-Queue: Auto-Submit <auto-submit@pigweed.google.com.iam.gserviceaccount.com>

3 files changed, 25 insertions, 18 deletions

diff --git a/pw_rpc/java/main/dev/pigweed/pw_rpc/Client.java b/pw_rpc/java/main/dev/pigweed/pw_rpc/Client.java
index f4d187351..a62d77d76 100644
--- a/pw_rpc/java/main/dev/pigweed/pw_rpc/Client.java
+++ b/pw_rpc/java/main/dev/pigweed/pw_rpc/Client.java
@@ -198,31 +198,42 @@ public class Client {
     StreamObserverCall<?, ?> call =
         packet.getType().equals(PacketType.SERVER_STREAM) ? rpcs.getPending(rpc) : rpcs.clear(rpc);
     if (call == null) {
-      logger.atInfo().log(
-          "Ignoring packet for RPC (%s) that isn't pending. Pending RPCs are: %s", rpc, rpcs);
+      logger.atFine().log(
+          "Ignoring packet for %s, which isn't pending. Pending RPCs are %s", rpc, rpcs);
       sendError(channel, packet, Status.FAILED_PRECONDITION);
       return true;
     }
 
     switch (packet.getType()) {
-      case SERVER_ERROR:
+      case SERVER_ERROR: {
         Status status = decodeStatus(packet);
-        logger.atWarning().log("RPC %s failed with error %s", rpc, status);
+        logger.atWarning().log("%s failed with error %s", rpc, status);
         call.onError(status);
         break;
-      case RESPONSE:
+      }
+      case RESPONSE: {
+        Status status = decodeStatus(packet);
         // Server streaming an unary RPCs include a payload with their response packet.
         if (!rpc.method().isServerStreaming()) {
+          logger.atFiner().log("%s completed with status %s and %d B payload",
+              rpc,
+              status,
+              packet.getPayload().size());
           call.onNext(packet.getPayload());
+        } else {
+          logger.atFiner().log("%s completed with status %s", rpc, status);
         }
-        call.onCompleted(decodeStatus(packet));
+        call.onCompleted(status);
         break;
+      }
       case SERVER_STREAM:
+        logger.atFiner().log(
+            "%s received server stream with %d B payload", rpc, packet.getPayload().size());
         call.onNext(packet.getPayload());
         break;
       default:
         logger.atWarning().log(
-            "Unexpected PacketType %d for RPC %s", packet.getType().getNumber(), rpc);
+            "%s received unexpected PacketType %d", rpc, packet.getType().getNumber());
     }
 
     return true;
diff --git a/pw_rpc/java/main/dev/pigweed/pw_rpc/PendingRpc.java b/pw_rpc/java/main/dev/pigweed/pw_rpc/PendingRpc.java
index 6cc9b4719..59e210d8a 100644
--- a/pw_rpc/java/main/dev/pigweed/pw_rpc/PendingRpc.java
+++ b/pw_rpc/java/main/dev/pigweed/pw_rpc/PendingRpc.java
@@ -32,7 +32,6 @@ public abstract class PendingRpc {
 
   @Override
   public final String toString() {
-    return String.format(
-        Locale.ENGLISH, "PendingRpc(channel=%d, method=%s)", channel().id(), method());
+    return String.format(Locale.ENGLISH, "RpcCall[%s channel=%d]", method(), channel().id());
   }
 }
diff --git a/pw_rpc/java/main/dev/pigweed/pw_rpc/RpcManager.java b/pw_rpc/java/main/dev/pigweed/pw_rpc/RpcManager.java
index 2f8b8699d..bc690bb28 100644
--- a/pw_rpc/java/main/dev/pigweed/pw_rpc/RpcManager.java
+++ b/pw_rpc/java/main/dev/pigweed/pw_rpc/RpcManager.java
@@ -37,7 +37,7 @@ public class RpcManager {
   public synchronized StreamObserverCall<?, ?> start(
       PendingRpc rpc, StreamObserverCall<?, ?> call, @Nullable MessageLite payload)
       throws ChannelOutputException {
-    logger.atFine().log("Start %s", rpc);
+    logger.atFine().log("%s starting", rpc);
     rpc.channel().send(Packets.request(rpc, payload));
     return pending.put(rpc, call);
   }
@@ -51,11 +51,11 @@ public class RpcManager {
   @Nullable
   public synchronized StreamObserverCall<?, ?> open(
       PendingRpc rpc, StreamObserverCall<?, ?> call, @Nullable MessageLite payload) {
-    logger.atFine().log("Open %s", rpc);
+    logger.atFine().log("%s opening", rpc);
     try {
       rpc.channel().send(Packets.request(rpc, payload));
     } catch (ChannelOutputException e) {
-      logger.atFine().withCause(e).log(
+      logger.atFiner().withCause(e).log(
           "Ignoring error opening %s; listening for unrequested responses", rpc);
     }
     return pending.put(rpc, call);
@@ -67,7 +67,7 @@ public class RpcManager {
       throws ChannelOutputException {
     StreamObserverCall<?, ?> call = pending.remove(rpc);
     if (call != null) {
-      logger.atFine().log("Cancel %s", rpc);
+      logger.atFine().log("%s was cancelled", rpc);
       rpc.channel().send(Packets.cancel(rpc));
     }
     return call;
@@ -88,6 +88,7 @@ public class RpcManager {
       throws ChannelOutputException {
     StreamObserverCall<?, ?> call = pending.get(rpc);
     if (call != null) {
+      logger.atFiner().log("%s client stream closed", rpc);
       rpc.channel().send(Packets.clientStreamEnd(rpc));
     }
     return call;
@@ -95,11 +96,7 @@ public class RpcManager {
 
   @Nullable
   public synchronized StreamObserverCall<?, ?> clear(PendingRpc rpc) {
-    StreamObserverCall<?, ?> call = pending.remove(rpc);
-    if (call != null) {
-      logger.atFine().log("Clear %s", rpc);
-    }
-    return call;
+    return pending.remove(rpc);
   }
 
   @Nullable