Datanode service restarted after upgrade from 1.3.0 to 1.4.1

[yazynin]

Datanode service restarted after upgrade from 1.3.0 to 1.4.1:

last log is:

2024-12-25 14:04:13,348 INFO org.apache.hadoop.ozone.container.common.transport.server.ratis.XceiverServerRatis: Leader change notification received for group: group-491158183723 with new leaderId: e4cedf5d-b6e2-4a38-8611-5382b0d6f0d2
2024-12-25 14:04:13,348 INFO org.apache.ratis.server.RaftServer$Division: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-491158183723: change Leader from null to e4cedf5d-b6e2-4a38-8611-5382b0d6f0d2 at term 259 for appendEntries, leader elected after 26ms
2024-12-25 14:04:13,352 INFO org.apache.ratis.server.RaftServer$Division: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-491158183723: set configuration conf: {index: 377268, cur=peers:[44b68ec7-884e-4447-ac0c-61e1206a3833|10.10.2.177:9856, e4cedf5d-b6e2-4a38-8611-5382b0d6f0d2|10.10.2.31:9856, 9c64df28-43a2-43ce-8056-370c156e6a13|10.10.2.101:9856]|listeners:[], old=null}
2024-12-25 14:04:13,353 INFO org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogWorker: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-491158183723-SegmentedRaftLogWorker: Rolling segment log-377266_377267 to index:377267
2024-12-25 14:04:13,354 INFO org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogWorker: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-491158183723-SegmentedRaftLogWorker: Rolled log segment from /opt/ozone/storage/674ab10f-fbda-4d2e-98a0-491158183723/current/log_inprogress_377266 to /opt/ozone/storage/674ab10f-fbda-4d2e-98a0-491158183723/current/log_377266-377267
2024-12-25 14:04:13,355 INFO org.apache.ratis.server.raftlog.segmented.BufferedWriteChannel: open log_inprogress_377268 at position 0
2024-12-25 14:04:13,368 INFO org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogWorker: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-491158183723-SegmentedRaftLogWorker: created new log segment /opt/ozone/storage/674ab10f-fbda-4d2e-98a0-491158183723/current/log_inprogress_377268
2024-12-25 14:04:14,441 INFO org.apache.hadoop.ozone.container.common.interfaces.ContainerDeletionChoosingPolicyTemplate: Chosen 0/50000 blocks from 0 candidate containers.
2024-12-25 14:05:14,444 INFO org.apache.hadoop.ozone.container.common.interfaces.ContainerDeletionChoosingPolicyTemplate: Chosen 0/50000 blocks from 0 candidate containers.
2024-12-25 14:05:18,238 WARN org.apache.ratis.grpc.server.GrpcLogAppender: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-1C56C70DF2D9->eded481d-809c-44b2-b0fc-dbd30134725e-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: Network closed for unknown reason
2024-12-25 14:05:18,238 WARN org.apache.ratis.grpc.server.GrpcLogAppender: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-BF1FAD58CB68->eded481d-809c-44b2-b0fc-dbd30134725e-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: Network closed for unknown reason
2024-12-25 14:05:18,239 WARN org.apache.ratis.grpc.server.GrpcLogAppender: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-438B47C11C67->eded481d-809c-44b2-b0fc-dbd30134725e-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: Network closed for unknown reason
2024-12-25 14:05:18,239 WARN org.apache.ratis.grpc.server.GrpcLogAppender: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-438B47C11C67->eded481d-809c-44b2-b0fc-dbd30134725e-GrpcLogAppender: Follower failed (request=null, errorCount=1); keep nextIndex (389551) unchanged and retry.
2024-12-25 14:05:18,239 WARN org.apache.ratis.grpc.server.GrpcLogAppender: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-BF1FAD58CB68->eded481d-809c-44b2-b0fc-dbd30134725e-GrpcLogAppender: Follower failed (request=null, errorCount=1); keep nextIndex (385299) unchanged and retry.
2024-12-25 14:05:18,239 WARN org.apache.ratis.grpc.server.GrpcLogAppender: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-1C56C70DF2D9->eded481d-809c-44b2-b0fc-dbd30134725e-GrpcLogAppender: Follower failed (request=null, errorCount=1); keep nextIndex (387678) unchanged and retry.
2024-12-25 14:05:19,277 WARN org.apache.ratis.grpc.server.GrpcLogAppender: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-438B47C11C67->eded481d-809c-44b2-b0fc-dbd30134725e-GrpcLogAppender: Follower failed (request=null, errorCount=5); keep nextIndex (389552) unchanged and retry.
2024-12-25 14:05:19,304 WARN org.apache.ratis.grpc.server.GrpcLogAppender: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-438B47C11C67->eded481d-809c-44b2-b0fc-dbd30134725e-GrpcLogAppender: Follower failed (request=null, errorCount=7); keep nextIndex (389553) unchanged and retry.
2024-12-25 14:05:19,306 WARN org.apache.ratis.grpc.server.GrpcLogAppender: 44b68ec7-884e-4447-ac0c-61e1206a3833@group-438B47C11C67->eded481d-809c-44b2-b0fc-dbd30134725e-GrpcLogAppender: Follower failed (request=null, errorCount=9); keep nextIndex (389555) unchanged and retry.
2024-12-25 14:05:20,978 WARN org.apache.ratis.server.impl.FollowerState: Unexpected long sleep: sleep 5075ms but took extra 1034329775ns (> threshold = 300ms)
2024-12-25 14:05:20,978 WARN org.apache.ratis.server.impl.FollowerState: Unexpected long sleep: sleep 5029ms but took extra 921326059ns (> threshold = 300ms)
2024-12-25 14:05:20,979 WARN org.apache.ratis.server.impl.FollowerState: Unexpected long sleep: sleep 5086ms but took extra 451680803ns (> threshold = 300ms)
2024-12-25 14:05:29,965 INFO org.apache.hadoop.ozone.HddsDatanodeService: STARTUP_MSG:
/************************************************************
STARTUP_MSG: Starting HddsDatanodeService

any suggestions please

[yazynin]

Looks like bug in Ratis 3.1.1, update to master fix issue

[rkurniawati]

@yazynin Which Ratis version fixes this issue?

[yazynin]

3.1.2