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>
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 f4d1873..a62d77d 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 @@
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 6cc9b47..59e210d 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 @@
@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 2f8b869..bc690bb 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 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 @@
@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 @@
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 @@
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 @@
@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
