[
https://issues.apache.org/jira/browse/HDDS-14078?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Saketa Chalamchala updated HDDS-14078:
--------------------------------------
Parent: HDDS-12090
Issue Type: Sub-task (was: Bug)
> 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: Sub-task
> Components: Ozone Manager
> Reporter: Saketa Chalamchala
> Priority: Major
>
> 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]
