Wei-Chiu Chuang created RATIS-2694:
--------------------------------------
Summary: GrpcServerProtocolService always logs Completed
INSTALL_SNAPSHOT, lastReply: null
Key: RATIS-2694
URL: https://issues.apache.org/jira/browse/RATIS-2694
Project: Ratis
Issue Type: Improvement
Components: gRPC
Affects Versions: 3.2.1
Reporter: Wei-Chiu Chuang
h3. Problem
For gRPC Raft RPCs that use {{ServerRequestStreamObserver}} with *ordered*
replies ({{replyInOrder == true}}), including *INSTALL_SNAPSHOT* and
append-entries with entries, each response is sent on the stream in {{onNext}}
via {{handleReply(reply)}}. In the ordered path, the internal
{{CompletableFuture}} chain completes with *null* after {{handleReply}}
({{thenCombine}} returns {{null}}).
When the client completes the stream, {{onCompleted()}} logs:
{code}
Completed INSTALL_SNAPSHOT, lastReply: null
{code}
That line uses the *terminal value of the ordering future*, not the last
{{InstallSnapshotReplyProto}} actually sent on the stream. The meaningful reply
is already logged by {{SnapshotInstallationHandler}}, e.g.:
{code}
reply installSnapshot:
<leader><-<follower>#0:FAIL-t47,IN_PROGRESS,snapshotIndex=0
{code}
Operators often interpret {{lastReply: null}} as a failed or missing RPC,
especially during long follower catch-up when INSTALL_SNAPSHOT and {{Failed
appendEntries as snapshot installation is in progress}} repeat.
*Relevant code:*
{{ratis-grpc/src/main/java/org/apache/ratis/grpc/server/GrpcServerProtocolService.java}},
inner class {{ServerRequestStreamObserver}} — {{handleReply}}, ordered
{{onNext}}, {{onCompleted}}.
h3. Steps to reproduce
# Run a multi-node Raft group over gRPC (e.g. Ozone SCM/OM HA follower far
behind the leader).
# Enable INFO for {{org.apache.ratis.grpc.server.GrpcServerProtocolService}}
and {{org.apache.ratis.server.impl.SnapshotInstallationHandler}}.
# Observe install-snapshot activity on the follower.
*Actual:* Pairs such as {{reply installSnapshot: ...}} followed by {{Completed
INSTALL_SNAPSHOT, lastReply: null}}.
*Expected:* The completion log should show the *last reply sent on the stream*
(e.g. via existing {{replyToString}} /
{{ServerStringUtils.toInstallSnapshotReplyString}}), or an explicit value such
as {{none}} if no reply was sent.
h3. Proposed fix
In {{ServerRequestStreamObserver}}:
# Add {{AtomicReference<REPLY> lastReplySent}}.
# In {{handleReply}}, set {{lastReplySent}} before
{{responseObserver.onNext(reply)}}.
# In {{onCompleted}}, log {{replyToString(lastReplySent.get())}} when non-null,
else {{"none"}}, instead of the terminal {{requestFuture}} value.
Apply consistently for all ops using this observer (INSTALL_SNAPSHOT, ordered
APPEND_ENTRIES, etc.).
h3. Test plan
* Unit/integration: ordered stream, one or more replies, complete stream;
assert completion log contains {{replyToString}} of the last reply, not
{{null}}.
* Manual: SCM/OM HA follower install snapshot; {{Completed INSTALL_SNAPSHOT,
lastReply:}} should align with the last {{reply installSnapshot:}} line.
h3. Impact
* *User:* Clearer HA troubleshooting; fewer false alarms.
* *Risk:* Logging-only if limited to the completion line; no protocol change.
h3. Related issues (not duplicates)
||Issue||Status||Relationship||
|[RATIS-2347|https://issues.apache.org/jira/browse/RATIS-2347]|Resolved
(3.2.1)|Same log line; fixes *NPE* when reply is null (timeout). Still prints
{{null}}; does not log the streamed reply.|
|[RATIS-2244|https://issues.apache.org/jira/browse/RATIS-2244]|Resolved
(3.2.0)|Same log pattern during bootstrap; {{BatchLogger}} batching only; does
not change {{lastReply}} semantics.|
|[RATIS-2348|https://issues.apache.org/jira/browse/RATIS-2348]|Resolved
(3.2.1)|{{GrpcLogAppender}} log flood when notification fails in the state
machine.|
h3. Not duplicates (snapshot behavior)
[RATIS-1481|https://issues.apache.org/jira/browse/RATIS-1481],
[RATIS-2045|https://issues.apache.org/jira/browse/RATIS-2045],
[RATIS-2140|https://issues.apache.org/jira/browse/RATIS-2140],
[RATIS-2145|https://issues.apache.org/jira/browse/RATIS-2145],
[RATIS-2152|https://issues.apache.org/jira/browse/RATIS-2152],
[RATIS-2500|https://issues.apache.org/jira/browse/RATIS-2500] — real
install-snapshot bugs; attachments often show {{lastReply: null}} as incidental
context.
Downstream: [HDDS-10696|https://issues.apache.org/jira/browse/HDDS-10696]
(Ozone) — empty/failed snapshot install; not this logging issue.
h3. Context
Observed on Apache Ratis 3.2.1 with Ozone SCM HA follower snapshot catch-up.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
