PutBlock error

[sokui]

Hi community,

We are seeing some PutBlock error logs from s3g logs. It seems the ratis group not found. Do you know what is the reason for that, and how to fix it?

2024-02-26 20:02:55 ERROR java.util.concurrent.ThreadPoolExecutor$Worker@3bb7cc93[State = -1, empty queue] OrderedAsync:175 - Failed to send request, message=cmdType: PutBlock
traceID: ""
containerID: 3464211
datanodeUuid: "bcb4c955-c601-4040-a06a-b89dc90066af"
putBlock {
blockData {
blockID {
containerID: 3464211
localID: 109611004790553794
blockCommitSequenceId: 0
}
metadata {
key: "TYPE"
value: "KEY"
}
chunks {
chunkName: "109611004790553794_chunk_1"
offset: 0
len: 4194304
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: "\247\220ko"
checksums: "P`\254G"
checksums: "\314\236B("
checksums: "r\256\276\025"
}
}
chunks {
chunkName: "109611004790553794_chunk_2"
offset: 4194304
len: 4194304
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: "ul\316\267"
checksums: "\310\241\244\264"
checksums: "\202\274\302\266"
checksums: "\003\205\005\330"
}
}
chunks {
chunkName: "109611004790553794_chunk_3"
offset: 8388608
len: 4194304
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: "\217\253\331\b"
checksums: "K\355\347\243"
checksums: "\333\251/\310"
checksums: "\002\364\236}"
}
}
chunks {
chunkName: "109611004790553794_chunk_4"
offset: 12582912
len: 4194304
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: ",m\272\260"
checksums: "\271\205\262z"
checksums: "\360\207\306\\"
checksums: "\374\b\345\301"
}
}
chunks {
chunkName: "109611004790553794_chunk_5"
offset: 16777216
len: 4194304
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: "c\201\324\274"
checksums: "\377.\243\351"
checksums: "P\233\020\344"
checksums: " \023\322\370"
}
}
chunks {
chunkName: "109611004790553794_chunk_6"
offset: 20971520
len: 4194304
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: "\257k\352|"
checksums: "\307\331\376\270"
checksums: "D\267\374\341"
checksums: "\027\310\245-"
}
}
chunks {
chunkName: "109611004790553794_chunk_7"
offset: 25165824
len: 4194304
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: "\274\227!-"
checksums: "\230C\310\303"
checksums: "a!\323l"
checksums: "\205r\020$"
}
}
chunks {
chunkName: "109611004790553794_chunk_8"
offset: 29360128
len: 4194304
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: "\3416\266\327"
checksums: "\247PLZ"
checksums: "\307\361\333k"
checksums: "\237\033\020!"
}
}
}
eof: false
}
, data.size=0
java.util.concurrent.CompletionException: org.apache.ratis.protocol.exceptions.AlreadyClosedException: SlidingWindow$Client:client-B79593EEED77->RAFT is closed.
at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346)
at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632)
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
at org.apache.ratis.client.impl.OrderedAsync$PendingOrderedRequest.fail(OrderedAsync.java:104)
at org.apache.ratis.util.SlidingWindow$Client.alreadyClosed(SlidingWindow.java:378)
at org.apache.ratis.util.SlidingWindow$Client.fail(SlidingWindow.java:366)
at org.apache.ratis.client.impl.OrderedAsync.failAllAsyncRequests(OrderedAsync.java:148)
at org.apache.ratis.client.impl.OrderedAsync.handleAsyncRetryFailure(OrderedAsync.java:152)
at org.apache.ratis.client.impl.OrderedAsync.lambda$sendRequest$10(OrderedAsync.java:258)
at java.base/java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:986)
at java.base/java.util.concurrent.CompletableFuture.uniExceptionallyStage(CompletableFuture.java:1004)
at java.base/java.util.concurrent.CompletableFuture.exceptionally(CompletableFuture.java:2307)
at org.apache.ratis.client.impl.OrderedAsync.sendRequest(OrderedAsync.java:247)
at org.apache.ratis.client.impl.OrderedAsync.sendRequestWithRetry(OrderedAsync.java:194)
at org.apache.ratis.util.SlidingWindow$Client.sendOrDelayRequest(SlidingWindow.java:280)
at org.apache.ratis.util.SlidingWindow$Client.retry(SlidingWindow.java:296)
at org.apache.ratis.client.impl.OrderedAsync.lambda$scheduleWithTimeout$7(OrderedAsync.java:228)
at org.apache.ratis.util.TimeoutScheduler.lambda$onTimeout$0(TimeoutScheduler.java:141)
at org.apache.ratis.util.TimeoutScheduler.lambda$onTimeout$1(TimeoutScheduler.java:155)
at org.apache.ratis.util.LogUtils.runAndLog(LogUtils.java:38)
at org.apache.ratis.util.LogUtils$1.run(LogUtils.java:79)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.apache.ratis.protocol.exceptions.AlreadyClosedException: SlidingWindow$Client:client-B79593EEED77->RAFT is closed.
... 23 more
Caused by: org.apache.ratis.protocol.exceptions.RaftRetryFailureException: Failed RaftClientRequest:client-B79593EEED77->bcb4c955-c601-4040-a06a-b89dc90066af@group-788B5A4CE924, cid=68140096, seq=1*, Watch(0), null for 24 attempts with RequestTypeDependentRetryPolicy{WRITE->ExceptionDependentRetry(maxAttempts=2147483647; defaultPolicy=MultipleLinearRandomRetry[5x5s, 5x10s, 5x15s, 5x20s, 5x25s, 10x60s]; map={org.apache.ratis.protocol.exceptions.GroupMismatchException->NoRetry, org.apache.ratis.protocol.exceptions.NotReplicatedException->NoRetry, org.apache.ratis.protocol.exceptions.ResourceUnavailableException->org.apache.ratis.retry.ExponentialBackoffRetry@67013dc2, org.apache.ratis.protocol.exceptions.StateMachineException->NoRetry, org.apache.ratis.protocol.exceptions.TimeoutIOException->org.apache.ratis.retry.ExponentialBackoffRetry@67013dc2}), WATCH->ExceptionDependentRetry(maxAttempts=2147483647; defaultPolicy=MultipleLinearRandomRetry[5x5s, 5x10s, 5x15s, 5x20s, 5x25s, 10x60s]; map={org.apache.ratis.protocol.exceptions.GroupMismatchException->NoRetry, org.apache.ratis.protocol.exceptions.NotReplicatedException->NoRetry, org.apache.ratis.protocol.exceptions.ResourceUnavailableException->org.apache.ratis.retry.ExponentialBackoffRetry@67013dc2, org.apache.ratis.protocol.exceptions.StateMachineException->NoRetry, org.apache.ratis.protocol.exceptions.TimeoutIOException->NoRetry})}
at org.apache.ratis.client.impl.RaftClientImpl.noMoreRetries(RaftClientImpl.java:295)
... 20 more
Caused by: org.apache.ratis.protocol.exceptions.AlreadyClosedException: client-B79593EEED77->bcb4c955-c601-4040-a06a-b89dc90066af is closed.
at org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers.onNext(GrpcClientProtocolClient.java:360)
at org.apache.ratis.grpc.client.GrpcClientRpc.sendRequestAsync(GrpcClientRpc.java:71)
at org.apache.ratis.client.impl.OrderedAsync.sendRequest(OrderedAsync.java:241)
... 14 more
2024-02-26 20:02:55 WARN qtp237344028-1637216 KeyOutputStream:309 - Encountered exception java.io.IOException: Unexpected Storage Container Exception: java.util.concurrent.CompletionException: Failed to write chunk 109611004790553794_chunk_1 into block conID: 3464211 locID: 109611004790553794 bcsId: 0 on the pipeline Pipeline[ Id: 1532479c-fc47-4313-be18-788b5a4ce924, Nodes: bcb4c955-c601-4040-a06a-b89dc90066af{ip: 100.114.76.13, host: ozone-dn-prod-37.ozone-dn.prod.svc.kube.k8s.cloud.abc.com, ports: [REPLICATION=9886, RATIS=9858, RATIS_ADMIN=9857, RATIS_SERVER=9856, STANDALONE=9859], networkLocation: /default-rack, certSerialId: null, persistedOpState: IN_SERVICE, persistedOpStateExpiryEpochSec: 0}, ReplicationConfig: RATIS/ONE, State:OPEN, leaderId:bcb4c955-c601-4040-a06a-b89dc90066af, CreationTimestamp2023-11-20T04:38:24.603Z[UTC]]. The last committed block length is 0, uncommitted data length is 33554432 retry count 0

[sokui]

I did not see any ERROR logs from this particular datanode ozone-dn-prod-37. Only some WARN logs:

2024-02-26 15:32:51 WARN  bcb4c955-c601-4040-a06a-b89dc90066af@group-32DF171175D5->4bedcee5-6c51-4017-a6a0-a1278b36b157-GrpcLogAppender-LogAppenderDaemon GrpcLogAppender:171 - bcb4c955-c601-4040-a06a-b89dc90066af@g
roup-32DF171175D5->4bedcee5-6c51-4017-a6a0-a1278b36b157-GrpcLogAppender: Wait interrupted by java.lang.InterruptedException
2024-02-26 15:32:51 WARN  bcb4c955-c601-4040-a06a-b89dc90066af@group-32DF171175D5->cc290665-2245-4c49-8a98-0c8ef83d5590-GrpcLogAppender-LogAppenderDaemon GrpcLogAppender:171 - bcb4c955-c601-4040-a06a-b89dc90066af@g
roup-32DF171175D5->cc290665-2245-4c49-8a98-0c8ef83d5590-GrpcLogAppender: Wait interrupted by java.lang.InterruptedException

[sokui]

@kerneltime thanks for looking. First of all, how do you know group-788B5A4CE924 is for ratis 3 way replicated ring (you mean the pipeline has 3 datanodes, right?)?

[kerneltime]

@sokui group- is used to identify pipeline that is used for writes. Essentially OM selects a container for writes which is mapped to a pipeline which has it's own id within Ratis code.

[sokui]

@kerneltime yeah, I understand this. My question was actually how you know the pipeline has the replication factor of 3. In our usage, we only use the pipeline with replication factor of 1. I guess you just assume the default setting, which is replication 3, right?

[sokui]

Hi @kerneltime ,

The previous log was gone. But we see this kind of errors a lot. I just picked up another datanode which has the same issue. The problematic ratis group for this datanode is group-5C55D7AFAED5, and the relevant logs are as follows. Do you know what the problem is?

2024-03-08 23:36:37 INFO  aa5e0d62-ed61-466a-8647-441ceb78dd71@group-5C55D7AFAED5-LeaderStateImpl RaftServer$Division:299 - aa5e0d62-ed61-466a-8647-441ceb78dd71@group-5C55D7AFAED5: changes role from    LEADER to FOLLOWER at term 23 for St
epDownReason:JVM_PAUSE
2024-03-08 23:36:37 INFO  aa5e0d62-ed61-466a-8647-441ceb78dd71@group-5C55D7AFAED5-LeaderStateImpl RoleInfo:93 - aa5e0d62-ed61-466a-8647-441ceb78dd71: shutdown aa5e0d62-ed61-466a-8647-441ceb78dd71@group-5C55D7AFAED5-LeaderStateImpl
2024-03-08 23:36:37 INFO  aa5e0d62-ed61-466a-8647-441ceb78dd71@group-5C55D7AFAED5-LeaderStateImpl PendingRequests:282 - aa5e0d62-ed61-466a-8647-441ceb78dd71@group-5C55D7AFAED5-PendingRequests: sendNotLeaderResponses
Exception in thread "aa5e0d62-ed61-466a-8647-441ceb78dd71@group-5C55D7AFAED5-LeaderStateImpl" java.lang.IllegalStateException: Entry not found for key 334243 in map OrderedStreamObservers
2024-03-08 23:36:37 INFO  grpc-default-executor-40811 GrpcLogAppender:339 - aa5e0d62-ed61-466a-8647-441ceb78dd71@group-32D5B33B456A->81bf0ca4-8356-4c9e-9f8d-2df0bf1a224f-AppendLogResponseHandler: follower responses appendEntries COMPLETED
        at org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:72)
        at org.apache.ratis.util.CollectionUtils.removeExisting(CollectionUtils.java:120)
        at org.apache.ratis.grpc.server.GrpcClientProtocolService$OrderedStreamObservers.removeExisting(GrpcClientProtocolService.java:115)
        at org.apache.ratis.grpc.server.GrpcClientProtocolService$OrderedRequestStreamObserver.cleanup(GrpcClientProtocolService.java:395)
        at org.apache.ratis.grpc.server.GrpcClientProtocolService$OrderedRequestStreamObserver.close(GrpcClientProtocolService.java:389)
        at org.apache.ratis.grpc.server.GrpcClientProtocolService$OrderedRequestStreamObserver.access$100(GrpcClientProtocolService.java:316)
        at org.apache.ratis.grpc.server.GrpcClientProtocolService$OrderedStreamObservers.closeAllExisting(GrpcClientProtocolService.java:126)
        at org.apache.ratis.grpc.server.GrpcClientProtocolService.closeAllOrderedRequestStreamObservers(GrpcClientProtocolService.java:159)
        at org.apache.ratis.grpc.server.GrpcService.notifyNotLeader(GrpcService.java:287)
        at org.apache.ratis.server.impl.LeaderStateImpl.stop(LeaderStateImpl.java:337)
        at org.apache.ratis.server.impl.RoleInfo.shutdownLeaderState(RoleInfo.java:94)
        at org.apache.ratis.server.impl.RaftServerImpl.changeToFollower(RaftServerImpl.java:504)
        at org.apache.ratis.server.impl.RaftServerImpl.changeToFollowerAndPersistMetadata(RaftServerImpl.java:516)
        at org.apache.ratis.server.impl.LeaderStateImpl.stepDown(LeaderStateImpl.java:562)
        at org.apache.ratis.server.impl.LeaderStateImpl.lambda$submitStepDownEvent$8(LeaderStateImpl.java:557)
        at org.apache.ratis.server.impl.LeaderStateImpl$StateUpdateEvent.execute(LeaderStateImpl.java:118)
        at org.apache.ratis.server.impl.LeaderStateImpl$EventProcessor.run(LeaderStateImpl.java:634)

[sokui]

Is it because the pipeline/ratis group only has one datanode, there is no ratis followers, so the datanode got issues to step down the leadership?