Saketa Chalamchala created HDDS-14078:
-----------------------------------------
Summary: Install checkpoint on lagging OM fails during bootstrap
Key: HDDS-14078
URL: https://issues.apache.org/jira/browse/HDDS-14078
Project: Apache Ozone
Issue Type: Bug
Components: Ozone Manager
Reporter: Saketa Chalamchala
Triggered OM bootstrap on a lagging follower OM in the docker environment.
Install checkpoint never completes. Debug logging on the leader needs to be
improved.
```
Leader logs:
2025-12-04 16:46:48.440 | 2025-12-05 00:46:48,440
[om1@group-D66704EFC61C->om3-GrpcLogAppender-LogAppenderDaemon] INFO
server.GrpcLogAppender: om1@group-D66704EFC61C->om3-GrpcLogAppender: send
om1->om3#0-t1,notify:(t:1, i:981)
2025-12-04 16:46:48.444 | 2025-12-05 00:46:48,443 [timer6] WARN
server.GrpcLogAppender: om1@group-D66704EFC61C->om3-AppendLogResponseHandler:
received INCONSISTENCY reply with nextIndex 1, errorCount=1,
request=AppendEntriesRequest:cid=120166906,entriesCount=0 (Repeated 639 times
in the last 5.001s)
2025-12-04 16:46:48.445 | 2025-12-05 00:46:48,445
[om1@group-D66704EFC61C->om3-GrpcLogAppender-LogAppenderDaemon] INFO
server.GrpcLogAppender: om1@group-D66704EFC61C->om3-GrpcLogAppender: send
om1->om3#0-t1,notify:(t:1, i:981)
2025-12-04 16:46:48.446 | 2025-12-05 00:46:48,446 [timer7] INFO
server.GrpcLogAppender: om1@group-D66704EFC61C->om3-GrpcLogAppender:
notifyInstallSnapshot with firstAvailable=(t:1, i:981), followerNextIndex=1
(Repeated 1040 times in the last 5.001s)
2025-12-04 16:46:48.449 | 2025-12-05 00:46:48,448
[om1@group-D66704EFC61C->om3-GrpcLogAppender-LogAppenderDaemon] INFO
server.GrpcLogAppender: om1@group-D66704EFC61C->om3-GrpcLogAppender:
notifyInstallSnapshot with firstAvailable=(t:1, i:981), followerNextIndex=1
2025-12-04 16:46:48.449 | 2025-12-05 00:46:48,448
[om1@group-D66704EFC61C->om3-GrpcLogAppender-LogAppenderDaemon] INFO
server.GrpcLogAppender: om1@group-D66704EFC61C->om3-GrpcLogAppender: send
om1->om3#0-t1,notify:(t:1, i:981)
2025-12-04 16:46:48.449 | 2025-12-05 00:46:48,449 [grpc-default-executor-3]
WARN server.GrpcLogAppender:
om1@group-D66704EFC61C->om3-AppendLogResponseHandler: received INCONSISTENCY
reply with nextIndex 1, errorCount=1,
request=AppendEntriesRequest:cid=120166908,entriesCount=0
2025-12-04 16:46:48.452 | 2025-12-05 00:46:48,452
[om1@group-D66704EFC61C->om3-GrpcLogAppender-LogAppenderDaemon] INFO
server.GrpcLogAppender: om1@group-D66704EFC61C->om3-GrpcLogAppender: send
om1->om3#0-t1,notify:(t:1, i:981)
2025-12-04 16:46:48.455 | 2025-12-05 00:46:48,455
[om1@group-D66704EFC61C->om3-GrpcLogAppender-LogAppenderDaemon] INFO
server.GrpcLogAppender: om1@group-D66704EFC61C->om3-GrpcLogAppender: send
om1->om
...
2025-12-04 16:46:48.556 | 2025-12-05 00:46:48,555 [timer1] INFO
server.GrpcLogAppender:
om1@group-D66704EFC61C->om3-InstallSnapshotNotification: received a reply
om1<-om3#0:FAIL-t1,IN_PROGRESS,snapshotIndex=0 (Repeated 1070 times in the
last 5.001s)
2025-12-04 16:46:48.556 | 2025-12-05 00:46:48,556 [timer2] INFO
server.GrpcLogAppender:
om1@group-D66704EFC61C->om3-InstallSnapshotNotification: in progress,
(Repeated 1070 times in the last 5.002s)
2025-12-04 16:46:48.558 | 2025-12-05 00:46:48,558 [grpc-default-executor-3]
INFO server.GrpcLogAppender:
om1@group-D66704EFC61C->om3-InstallSnapshotNotification: received a reply
om1<-om3#0:FAIL-t1,IN_PROGRESS,snapshotIndex=0
2025-12-04 16:46:48.558 | 2025-12-05 00:46:48,558 [grpc-default-executor-3]
INFO server.GrpcLogAppender:
om1@group-D66704EFC61C->om3-InstallSnapshotNotification: in progress,
2025-12-04 16:46:48.558 | 2025-12-05 00:46:48,558
[om1@group-D66704EFC61C->om3-GrpcLogAppender-LogAppenderDaemon] INFO
server.GrpcLogAppender: om1@group-D66704EFC61C->om3-GrpcLogAppender: send
om1->om3#0-t1,notify:(t:1, i:981)
...
2025-12-04 16:46:49.251 | 2025-12-05 00:46:49,251
[om1@group-D66704EFC61C->om3-GrpcLogAppender-LogAppenderDaemon] INFO
server.GrpcLogAppender: om1@group-D66704EFC61C->om3-GrpcLogAppender: send
om1->om3#0-t1,notify:(t:1, i:981)
2025-12-04 16:46:49.285 | 2025-12-05 00:46:49,285 [grpc-default-executor-3]
WARN server.GrpcLogAppender:
om1@group-D66704EFC61C->om3-InstallSnapshotNotification: Failed InstallSnapshot
2025-12-04 16:46:49.285 | java.lang.IllegalStateException:
inProgressInstallSnapshotRequest: -1 is not eligible, firstAvailableLogIndex:
981
2025-12-04 16:46:49.285 | at
org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:65)
2025-12-04 16:46:49.285 | at
org.apache.ratis.server.impl.SnapshotInstallationHandler.notifyStateMachineToInstallSnapshot(SnapshotInstallationHandler.java:341)
2025-12-04 16:46:49.285 | at
org.apache.ratis.server.impl.SnapshotInstallationHandler.installSnapshotImpl(SnapshotInstallationHandler.java:137)
2025-12-04 16:46:49.285 | at
org.apache.ratis.server.impl.SnapshotInstallationHandler.installSnapshot(SnapshotInstallationHandler.java:107)
2025-12-04 16:46:49.285 | at
org.apache.ratis.server.impl.RaftServerImpl.installSnapshot(RaftServerImpl.java:1696)
2025-12-04 16:46:49.285 | at
org.apache.ratis.server.impl.RaftServerProxy.installSnapshot(RaftServerProxy.java:672)
2025-12-04 16:46:49.285 | at
org.apache.ratis.grpc.server.GrpcServerProtocolService$2.process(GrpcServerProtocolService.java:285)
2025-12-04 16:46:49.285 | at
org.apache.ratis.grpc.server.GrpcServerProtocolService$2.process(GrpcServerProtocolService.java:282)
2025-12-04 16:46:49.285 | at
org.apache.ratis.grpc.server.GrpcServerProtocolService$ServerRequestStreamObserver.onNext(GrpcServerProtocolService.java:152)
2025-12-04 16:46:49.285 | at
org.apache.ratis.thirdparty.io.grpc.stub.ServerCalls$StreamingServerCallHandler$StreamingServerCallListener.onMessage(ServerCalls.java:262)
2025-12-04 16:46:49.285 | at
org.apache.ratis.thirdparty.io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailableInternal(ServerCallImpl.java:334)
2025-12-04 16:46:49.285 | at
org.apache.ratis.thirdparty.io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailable(ServerCallImpl.java:319)
2025-12-04 16:46:49.285 | at
org.apache.ratis.thirdparty.io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1MessagesAvailable.runInContext(ServerImpl.java:834)
2025-12-04 16:46:49.285 | at
org.apache.ratis.thirdparty.io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
2025-12-04 16:46:49.285 | at
org.apache.ratis.thirdparty.io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
2025-12-04 16:46:49.285 | at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
2025-12-04 16:46:49.285 | at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
2025-12-04 16:46:49.285 | at
java.base/java.lang.Thread.run(Thread.java:1583)
2025-12-04 16:46:49.285 | 2025-12-05 00:46:49,285 [grpc-default-executor-3]
WARN server.GrpcLogAppender: om1@group-D66704EFC61C->om3-GrpcLogAppender:
Follower failed (request=null, errorCount=2); keep nextIndex (1) unchanged and
retry.
```
```
Follower logs keep repeating:
2025-12-04 16:46:43.427 | 2025-12-05 00:46:43,426 [grpc-default-executor-0]
INFO server.RaftServer$Division: om3@group-D66704EFC61C: Failed appendEntries
as previous log entry ((t:1, i:1010)) is not found
2025-12-04 16:46:43.434 | 2025-12-05 00:46:43,433 [grpc-default-executor-0]
INFO server.RaftServer$Division: om3@group-D66704EFC61C: appendEntries* reply
om1<-om3#120165868:FAIL-t1,INCONSISTENCY,nextIndex=1,followerCommit=0,matchIndex=-1
2025-12-04 16:46:43.467 | 2025-12-05 00:46:43,466 [grpc-default-executor-0]
INFO impl.SnapshotInstallationHandler: om3@group-D66704EFC61C: receive
installSnapshot: om1->om3#0-t1,notify:(t:1, i:981)
2025-12-04 16:46:43.468 | 2025-12-05 00:46:43,468 [grpc-default-executor-0]
INFO impl.SnapshotInstallationHandler: om3@group-D66704EFC61C: Received
notification to install snapshot at index 981
2025-12-04 16:46:43.474 | 2025-12-05 00:46:43,473 [grpc-default-executor-0]
INFO impl.SnapshotInstallationHandler: om3@group-D66704EFC61C:
notifyInstallSnapshot: nextIndex is 1 but the leader's first available index is
981.
2025-12-04 16:46:43.474 | 2025-12-05 00:46:43,473 [grpc-default-executor-0]
INFO ratis.OzoneManagerStateMachine: Received install snapshot notification
from OM leader: om1 with term index: (t:1, i:981)
2025-12-04 16:46:43.475 | 2025-12-05 00:46:43,474 [om3-InstallSnapshotThread]
INFO utils.RDBSnapshotProvider: Prepare to download the snapshot from leader OM
om1 and reloading state from the snapshot.
2025-12-04 16:46:43.481 | 2025-12-05 00:46:43,480 [om3-InstallSnapshotThread]
INFO ratis_snapshot.OmRatisSnapshotProvider: Downloading latest checkpoint from
Leader OM om1. Checkpoint: om.db-om1-1764895603475.tar URL:
http://om1:9874/v2/dbCheckpoint?includeSnapshotData=true&flushBeforeCheckpoint=true
2025-12-04 16:46:43.514 | 2025-12-05 00:46:43,514 [om3-InstallSnapshotThread]
ERROR impl.SnapshotInstallationHandler: om3@group-D66704EFC61C: Failed to
notify StateMachine to InstallSnapshot. Exception:
java.lang.reflect.UndeclaredThrowableException
2025-12-04 16:46:43.545 | 2025-12-05 00:46:43,545 [grpc-default-executor-0]
INFO impl.SnapshotInstallationHandler: om3@group-D66704EFC61C: set new
configuration configurationEntry \{ peers { id: "om1" address: "om1:9872"
startupRole: FOLLOWER } peers \{ id: "om3" address: "om3:9872" startupRole:
FOLLOWER } peers \{ id: "om2" address: "om2:9872" startupRole: FOLLOWER } }
from snapshot
2025-12-04 16:46:43.545 | 2025-12-05 00:46:43,545 [grpc-default-executor-0]
INFO server.RaftServer$Division: om3@group-D66704EFC61C: set configuration
conf: \{index: 0, cur=peers:[om1|om1:9872, om3|om3:9872,
om2|om2:9872]|listeners:[], old=null}
2025-12-04 16:46:43.549 | 2025-12-05 00:46:43,549 [grpc-default-executor-0]
INFO ratis.OzoneManagerStateMachine: notifyConfigurationChanged from Ratis:
term=0, index=0, New Peer list: om1(om1:9872), om3(om3:9872), om2(om2:9872),
New Listener list
2025-12-04 16:46:43.549 | 2025-12-05 00:46:43,549 [grpc-default-executor-0]
INFO impl.SnapshotInstallationHandler: om3@group-D66704EFC61C: reply
installSnapshot: om1<-om3#0:FAIL-t1,IN_PROGRESS,snapshotIndex=0
2025-12-04 16:46:43.551 | 2025-12-05 00:46:43,551 [grpc-default-executor-0]
INFO server.GrpcServerProtocolService: om3: Completed INSTALL_SNAPSHOT,
lastRequest: om1->om3#0-t1,notify:(t:1, i:981)
2025-12-04 16:46:43.552 | 2025-12-05 00:46:43,552 [grpc-default-executor-0]
INFO server.GrpcServerProtocolService: om3: Completed INSTALL_SNAPSHOT,
lastReply: null
```
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
