[RATIS-815] Log entry corrupted with 0 checksum

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: 0.5.0
• Fix Version/s: 1.0.0
• Component/s: server
• Assignee: Tsz-wo Sze
• Reporter: Attila Doroszlai
• Created: 13/Feb/20 13:18
• Updated: 04/Mar/20 02:17
• Resolved: 02/Mar/20 17:29

Description

After writing a few large keys (128MB) with very small chunks size (64KB) in Ozone, Ratis reports log entry corruption due to checksum error:

2020-02-13 12:01:41 INFO  SegmentedRaftLogWorker:396 - e5e4fd1e-aa81-48a2-98f9-b1ba24531624@group-B85226EEE236-SegmentedRaftLogWorker: Rolling segment log-62379_62465 to index:62465
2020-02-13 12:01:41 INFO  SegmentedRaftLogWorker:541 - e5e4fd1e-aa81-48a2-98f9-b1ba24531624@group-B85226EEE236-SegmentedRaftLogWorker: Rolled log segment from /data/metadata/ratis/f89fc072-9ee9-459b-85d1-b85226eee236/current/log_inprogress_62379 to /data/metadata/ratis/f89fc072-9ee9-459b-85d1-b85226eee236/current/log_62379-62465
2020-02-13 12:01:41 INFO  SegmentedRaftLogWorker:583 - e5e4fd1e-aa81-48a2-98f9-b1ba24531624@group-B85226EEE236-SegmentedRaftLogWorker: created new log segment /data/metadata/ratis/f89fc072-9ee9-459b-85d1-b85226eee236/current/log_inprogress_62466
2020-02-13 12:01:41 ERROR LogAppender:81 - e5e4fd1e-aa81-48a2-98f9-b1ba24531624@group-B85226EEE236->ac5b3434-874b-4375-8a03-989e8c7fb692-GrpcLogAppender-AppenderDaemon failed RaftLog
org.apache.ratis.server.raftlog.RaftLogIOException: org.apache.ratis.protocol.ChecksumException: Log entry corrupted: Calculated checksum is CDFED097 but read checksum is 00000000.
	at org.apache.ratis.server.raftlog.segmented.LogSegment.loadCache(LogSegment.java:311)
	at org.apache.ratis.server.raftlog.segmented.SegmentedRaftLog.get(SegmentedRaftLog.java:292)
	at org.apache.ratis.server.raftlog.segmented.SegmentedRaftLog.getEntryWithData(SegmentedRaftLog.java:297)
	at org.apache.ratis.server.impl.LogAppender.createRequest(LogAppender.java:213)
	at org.apache.ratis.grpc.server.GrpcLogAppender.appendLog(GrpcLogAppender.java:179)
	at org.apache.ratis.grpc.server.GrpcLogAppender.runAppenderImpl(GrpcLogAppender.java:122)
	at org.apache.ratis.server.impl.LogAppender$AppenderDaemon.run(LogAppender.java:77)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.ratis.protocol.ChecksumException: Log entry corrupted: Calculated checksum is CDFED097 but read checksum is 00000000.
	at org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogReader.decodeEntry(SegmentedRaftLogReader.java:312)
	at org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogReader.readEntry(SegmentedRaftLogReader.java:194)
	at org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogInputStream.nextEntry(SegmentedRaftLogInputStream.java:129)
	at org.apache.ratis.server.raftlog.segmented.LogSegment.readSegmentFile(LogSegment.java:98)
	at org.apache.ratis.server.raftlog.segmented.LogSegment$LogEntryLoader.load(LogSegment.java:202)
	at org.apache.ratis.server.raftlog.segmented.LogSegment.loadCache(LogSegment.java:309)
	... 7 more

Steps to reproduce:

1. Configure Ozone with 64KB chunk size and slightly higher buffer sizes:

ozone.scm.chunk.size: 64KB
ozone.client.stream.buffer.flush.size: 256KB
ozone.client.stream.buffer.max.size: 1MB

2. Run Freon:

ozone freon ockg -n 1 -t 1 -p warmup
ozone freon ockg -p test -t 8 -s 134217728 -n 32

Interestingly, even log_5106-5509 has invalid entry (according to log dump utility):

Processing Raft Log file: /data/metadata/ratis/f89fc072-9ee9-459b-85d1-b85226eee236/current/log_5106-5509 size:1030796
...
(t:1, i:5161), STATEMACHINELOGENTRY, client-296B6A48E40D, cid=3307
Exception in thread "main" org.apache.ratis.protocol.ChecksumException: Log entry corrupted: Calculated checksum is 926127AE but read checksum is 00000000.

Issue Links

• breaks: RATIS-822 BufferedWriteChannel may not flush correctly