[
https://issues.apache.org/jira/browse/CASSANDRA-21795?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Ke Han updated CASSANDRA-21795:
-------------------------------
Description:
Affects Version/s: 5.0.9, 5.0.x, 7.0 (trunk); by code inspection also 6.0 and
4.1.x
Environment: Single node, Linux 5.15 x86_64, ext4 (default mount options),
OpenJDK 11, commitlog_sync: batch. Built from source: trunk 95b178a1
(2026-10-17) and cassandra-5.0 dd48703a (2026-10-17); first seen on the 5.0.9
docker image. Power loss emulated with a device-mapper table swap to the
"error" target, which drops everything not yet written to the device.
*What happens*
Every lifecycle transaction log record (ADD, REMOVE, COMMIT, ABORT) is appended
with LogReplica.append -> FileUtils.appendAndSync -> FileUtils.write(file,
lines, APPEND, SYNC). FileUtils.write wraps the FileChannel in a
BufferedWriter, appends the line, calls SyncUtil.force(fc, true), and only then
leaves the try-with-resources block, whose close() flushes the BufferedWriter:
{code:java}
// src/java/org/apache/cassandra/io/util/FileUtils.java (trunk 95b178a1, lines
509-524)
try (FileChannel fc =
filePath.getFileSystem().provider().newFileChannel(filePath, optionsSet);
BufferedWriter writer = new BufferedWriter(new
OutputStreamWriter(Channels.newOutputStream(fc), CHARSET.newEncoder())))
{
for (CharSequence line: lines) {
writer.append(line);
writer.newLine();
}
if (sync)
{
SyncUtil.force(fc, true); // the line is still in the BufferedWriter
here
}
...
} // close() writes the line, after the force
{code}
So no record is durable when append() returns. strace of a compaction (trunk)
shows the fsync of the log immediately followed by the write of the record, for
every record; nothing syncs the COMMIT record before the obsolete SSTables are
deleted:
{noformat}
openat(AT_FDCWD, ".../ks/t-.../pa_txn_compaction_189d15e0-....log",
O_WRONLY|O_APPEND) = 648
fsync(648<.../pa_txn_compaction_189d15e0-....log>) = 0
write(648<.../pa_txn_compaction_189d15e0-....log>, "REMOVE:[.../ks/t-.../"...,
119) = 119
openat(AT_FDCWD, ".../ks/t-.../pa_txn_compaction_189d15e0-....log",
O_WRONLY|O_APPEND) = 648
fsync(648<.../pa_txn_compaction_189d15e0-....log>) = 0
write(648<.../pa_txn_compaction_189d15e0-....log>,
"COMMIT:[,0,0][2613697770]\n", 26) = 26
unlink(".../ks/t-.../pa-1-big-Data.db") = 0
unlink(".../ks/t-.../pa-1-big-Index.db") = 0
unlink(".../ks/t-.../pa-1-big-Statistics.db") = 0
unlink(".../ks/t-.../pa-1-big-CompressionInfo.db") = 0
unlink(".../ks/t-.../pa-1-big-Filter.db") <- power lost here
{noformat}
If the power fails while the obsolete SSTables are being deleted, and the file
system journal has committed in between (any fsync on the file system does
that, e.g. a commit-log sync of a concurrent write, or ext4's periodic commit),
the deletions and the log's new size are on disk but the COMMIT line is not:
after the restart the log ends with 26 zero bytes where the COMMIT record was,
the first input SSTable has lost half of its components, and the node refuses
to start:
{noformat}
ERROR [main] LogTransaction.java:580 - Unexpected disk state: failed to read
transaction log [pa_txn_compaction_189d15e0-cb31-11f1-bf62-c17df250b72a.log in
.../data/ks/t-1b255f4def2540a60000000000000004]
Files and contents follow:
.../data/ks/t-1b255f4def2540a60000000000000004/pa_txn_compaction_189d15e0-cb31-11f1-bf62-c17df250b72a.log
ADD:[.../data/ks/t-1b255f4def2540a60000000000000004/pa-5-big-,0,8][1455810341]
REMOVE:[.../data/ks/t-1b255f4def2540a60000000000000004/pa-1-big-,1792354695128,8][1782434158]
***Incomplete fileset detected for sstable [pa-1-big-]: number of files [4]
should have been [8].
REMOVE:[.../data/ks/t-1b255f4def2540a60000000000000004/pa-2-big-,1792354698840,8][1308462767]
REMOVE:[.../data/ks/t-1b255f4def2540a60000000000000004/pa-3-big-,1792354702352,8][2328435522]
REMOVE:[.../data/ks/t-1b255f4def2540a60000000000000004/pa-4-big-,1792354705912,8][3034924730]
***Failed to parse [ ]
ERROR [main] CassandraDaemon.java:1023 - Cannot remove temporary or obsoleted
files for ks.t due to a problem with transaction log files. Please check
records with problems in the log messages above and fix them. Refer to the 3.0
upgrading instructions in NEWS.txt for a description of transaction log files.
{noformat}
Tail of the log file after the restart (od -c):
{noformat}
0001060 5 9 1 2 , 8 ] [ 3 0 3 4 9 2 4 7
0001100 3 0 ] \n \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
0001120 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
{noformat}
Expected: the COMMIT record is durable before the first obsolete file is
deleted, so that recovery finishes the deletion (or, if the power fails before
the COMMIT is durable, rolls back onto intact input SSTables). The node starts
either way.
The same happens when the compacted table is a system table: a CREATE TABLE
flushes system_schema and starts a compaction of system_schema.columns; a power
cut during its deletions left 5.0.9 unable to start with "Data component is
missing for sstable .../system_schema/columns-.../nb-3-big" followed by
MissingColumns / CorruptSSTableException. The ordering also means the first ADD
record of a new flush transaction is not durable when the flush starts writing
(the log file exists, its directory is synced, but it is empty): a power cut
during a memtable flush then leaves a half-written SSTable with no ADD record,
which start-up treats as complete (seen as "CorruptSSTableException ...
EOFException" on a 0-byte Statistics.db on 5.0.9).
*Reproduce* (as root; CASSANDRA_HOME is an unpacked build; the strace inject
syntax needs strace >= 4.16)
{code:bash}
IMG=/dev/shm/cass.img; MNT=/mnt/cass; SECT=$((3*1024*1024*2))
truncate -s 3G $IMG; LOOP=$(losetup -f --show $IMG)
dmsetup create cass --table "0 $SECT linear $LOOP 0"
mkfs.ext4 -q /dev/mapper/cass; mkdir -p $MNT; mount /dev/mapper/cass $MNT
cd $CASSANDRA_HOME
sed -i -e 's/^commitlog_sync:.*/commitlog_sync: batch/' -e
'/^commitlog_sync_period:/d' conf/cassandra.yaml
cat >> conf/cassandra.yaml <<EOF
data_file_directories:
- $MNT/data
commitlog_directory: $MNT/commitlog
saved_caches_directory: $MNT/saved_caches
hints_directory: $MNT/hints
EOF
bin/cassandra -R > /tmp/c1.out 2>&1; sleep 60 # wait until it listens
for CQL clients
bin/cqlsh -e "CREATE KEYSPACE ks WITH replication = \{'class':
'SimpleStrategy', 'replication_factor': 1};
CREATE TABLE ks.t (id int PRIMARY KEY, v text) WITH compaction =
\{'class': 'SizeTieredCompactionStrategy'};"
bin/nodetool disableautocompaction ks t
for g in 1 2 3 4; do
bin/cqlsh -e "$(for i in $(seq $((g*100)) $((g*100+19))); do echo "INSERT
INTO ks.t (id, v) VALUES ($i, 'v$i');"; done)"
bin/nodetool flush ks t
done
sync -f $MNT
# freeze the node at the 5th unlink of the thread that deletes the obsolete
SSTables
strace -f -o /tmp/strace.log -e trace=unlink -e
inject=unlink:signal=KILL:when=5 -p $(pgrep -f CassandraDaemon) &
sleep 5; bin/nodetool compact ks t # the node is killed during the
deletions
sleep 2
# one fsync of an unrelated file commits the ext4 journal (stands for any
concurrent fsync)
python3 -c "import os; fd=os.open('$MNT/other', os.O_CREAT|os.O_WRONLY);
os.write(fd, b'x'); os.fsync(fd)"
# power cut: the device fails all further I/O, nothing is flushed first; then
"reboot"
dmsetup suspend --noflush --nolockfs cass
dmsetup load cass --table "0 $SECT error"; dmsetup resume cass
umount -l $MNT; sleep 1; dmsetup remove cass; losetup -d $LOOP
LOOP=$(losetup -f --show $IMG); mount $LOOP $MNT
od -c $MNT/data/ks/t-*/*_txn_compaction_*.log | tail -4 # COMMIT line
replaced by zeros
bin/cassandra -R -f # "Cannot remove
temporary or obsoleted files for ks.t ..."
{code}
Results (when=5, with the extra fsync): trunk 95b178a1 did not start in 5 of 9
runs, cassandra-5.0 dd48703a in 3 of 4 runs, always with the error above; in
the other runs the COMMIT line had reached the disk (the outcome depends on
whether the log's last data page is written out before the cut) and the node
recovered. The fsync-then-write order of every record was the same in every
run. Without a journal commit after the deletions (no extra fsync) the node
started in the run tried, because then neither the deletions nor the log's new
size were durable.
*Likely fix*
Flush the writer before forcing the channel in FileUtils.write (writer.flush(),
then SyncUtil.force), so that appendAndSync makes the record durable before it
returns. LogReplica.append relies on that for every record, and LogTransaction
deletes obsolete files right after the COMMIT append.
*Related*
- CASSANDRA-21649 (Review In Progress): REMOVE-record timestamp verification
fails after a crash during deletion of obsolete SSTables. Same start-up
refusal, different cause (deletion order); it does not change the missing sync
of the COMMIT record.
- CASSANDRA-18736 (fixed in 4.0.13): a streaming race leaves a corrupt
transaction log that prevents restart. Different cause.
- Regression from CASSANDRA-14134 (commit d6e508f33c1, 2018): before it,
FileUtils.write called Files.write(path, lines, CHARSET, options), which opens
the file with O_SYNC when SYNC is passed, so each record was durable when
write() returned. The patch replaced O_SYNC with "write all lines, then sync
once", but the sync runs before the BufferedWriter is flushed.
was:
*What happens*
Every lifecycle transaction log record (ADD, REMOVE, COMMIT, ABORT) is appended
with LogReplica.append -> FileUtils.appendAndSync -> FileUtils.write(file,
lines, APPEND, SYNC). FileUtils.write wraps the FileChannel in a
BufferedWriter, appends the line, calls SyncUtil.force(fc, true), and only then
leaves the try-with-resources block, whose close() flushes the BufferedWriter:
{code:java}
// src/java/org/apache/cassandra/io/util/FileUtils.java (trunk 95b178a1, lines
509-524)
try (FileChannel fc =
filePath.getFileSystem().provider().newFileChannel(filePath, optionsSet);
BufferedWriter writer = new BufferedWriter(new
OutputStreamWriter(Channels.newOutputStream(fc), CHARSET.newEncoder())))
{
for (CharSequence line: lines) {
writer.append(line);
writer.newLine();
}
if (sync)
{
SyncUtil.force(fc, true); // the line is still in the BufferedWriter
here
}
...
} // close() writes the line, after the force
{code}
So no record is durable when append() returns. strace of a compaction (trunk)
shows the fsync of the log immediately followed by the write of the record, for
every record; nothing syncs the COMMIT record before the obsolete SSTables are
deleted:
{noformat}
openat(AT_FDCWD, ".../ks/t-.../pa_txn_compaction_189d15e0-....log",
O_WRONLY|O_APPEND) = 648
fsync(648<.../pa_txn_compaction_189d15e0-....log>) = 0
write(648<.../pa_txn_compaction_189d15e0-....log>, "REMOVE:[.../ks/t-.../"...,
119) = 119
openat(AT_FDCWD, ".../ks/t-.../pa_txn_compaction_189d15e0-....log",
O_WRONLY|O_APPEND) = 648
fsync(648<.../pa_txn_compaction_189d15e0-....log>) = 0
write(648<.../pa_txn_compaction_189d15e0-....log>,
"COMMIT:[,0,0][2613697770]\n", 26) = 26
unlink(".../ks/t-.../pa-1-big-Data.db") = 0
unlink(".../ks/t-.../pa-1-big-Index.db") = 0
unlink(".../ks/t-.../pa-1-big-Statistics.db") = 0
unlink(".../ks/t-.../pa-1-big-CompressionInfo.db") = 0
unlink(".../ks/t-.../pa-1-big-Filter.db") <- power lost here
{noformat}
If the power fails while the obsolete SSTables are being deleted, and the file
system journal has committed in between (any fsync on the file system does
that, e.g. a commit-log sync of a concurrent write, or ext4's periodic commit),
the deletions and the log's new size are on disk but the COMMIT line is not:
after the restart the log ends with 26 zero bytes where the COMMIT record was,
the first input SSTable has lost half of its components, and the node refuses
to start:
{noformat}
ERROR [main] LogTransaction.java:580 - Unexpected disk state: failed to read
transaction log [pa_txn_compaction_189d15e0-cb31-11f1-bf62-c17df250b72a.log in
.../data/ks/t-1b255f4def2540a60000000000000004]
Files and contents follow:
.../data/ks/t-1b255f4def2540a60000000000000004/pa_txn_compaction_189d15e0-cb31-11f1-bf62-c17df250b72a.log
ADD:[.../data/ks/t-1b255f4def2540a60000000000000004/pa-5-big-,0,8][1455810341]
REMOVE:[.../data/ks/t-1b255f4def2540a60000000000000004/pa-1-big-,1792354695128,8][1782434158]
***Incomplete fileset detected for sstable [pa-1-big-]: number of files [4]
should have been [8].
REMOVE:[.../data/ks/t-1b255f4def2540a60000000000000004/pa-2-big-,1792354698840,8][1308462767]
REMOVE:[.../data/ks/t-1b255f4def2540a60000000000000004/pa-3-big-,1792354702352,8][2328435522]
REMOVE:[.../data/ks/t-1b255f4def2540a60000000000000004/pa-4-big-,1792354705912,8][3034924730]
***Failed to parse [ ]
ERROR [main] CassandraDaemon.java:1023 - Cannot remove temporary or obsoleted
files for ks.t due to a problem with transaction log files. Please check
records with problems in the log messages above and fix them. Refer to the 3.0
upgrading instructions in NEWS.txt for a description of transaction log files.
{noformat}
Tail of the log file after the restart (od -c):
{noformat}
0001060 5 9 1 2 , 8 ] [ 3 0 3 4 9 2 4 7
0001100 3 0 ] \n \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
0001120 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
{noformat}
Expected: the COMMIT record is durable before the first obsolete file is
deleted, so that recovery finishes the deletion (or, if the power fails before
the COMMIT is durable, rolls back onto intact input SSTables). The node starts
either way.
The same happens when the compacted table is a system table: a CREATE TABLE
flushes system_schema and starts a compaction of system_schema.columns; a power
cut during its deletions left 5.0.9 unable to start with "Data component is
missing for sstable .../system_schema/columns-.../nb-3-big" followed by
MissingColumns / CorruptSSTableException. The ordering also means the first ADD
record of a new flush transaction is not durable when the flush starts writing
(the log file exists, its directory is synced, but it is empty): a power cut
during a memtable flush then leaves a half-written SSTable with no ADD record,
which start-up treats as complete (seen as "CorruptSSTableException ...
EOFException" on a 0-byte Statistics.db on 5.0.9).
*Reproduce* (as root; CASSANDRA_HOME is an unpacked build; the strace inject
syntax needs strace >= 4.16)
{code:bash}
IMG=/dev/shm/cass.img; MNT=/mnt/cass; SECT=$((3*1024*1024*2))
truncate -s 3G $IMG; LOOP=$(losetup -f --show $IMG)
dmsetup create cass --table "0 $SECT linear $LOOP 0"
mkfs.ext4 -q /dev/mapper/cass; mkdir -p $MNT; mount /dev/mapper/cass $MNT
cd $CASSANDRA_HOME
sed -i -e 's/^commitlog_sync:.*/commitlog_sync: batch/' -e
'/^commitlog_sync_period:/d' conf/cassandra.yaml
cat >> conf/cassandra.yaml <<EOF
data_file_directories:
- $MNT/data
commitlog_directory: $MNT/commitlog
saved_caches_directory: $MNT/saved_caches
hints_directory: $MNT/hints
EOF
bin/cassandra -R > /tmp/c1.out 2>&1; sleep 60 # wait until it listens
for CQL clients
bin/cqlsh -e "CREATE KEYSPACE ks WITH replication = \{'class':
'SimpleStrategy', 'replication_factor': 1};
CREATE TABLE ks.t (id int PRIMARY KEY, v text) WITH compaction =
\{'class': 'SizeTieredCompactionStrategy'};"
bin/nodetool disableautocompaction ks t
for g in 1 2 3 4; do
bin/cqlsh -e "$(for i in $(seq $((g*100)) $((g*100+19))); do echo "INSERT
INTO ks.t (id, v) VALUES ($i, 'v$i');"; done)"
bin/nodetool flush ks t
done
sync -f $MNT
# freeze the node at the 5th unlink of the thread that deletes the obsolete
SSTables
strace -f -o /tmp/strace.log -e trace=unlink -e
inject=unlink:signal=KILL:when=5 -p $(pgrep -f CassandraDaemon) &
sleep 5; bin/nodetool compact ks t # the node is killed during the
deletions
sleep 2
# one fsync of an unrelated file commits the ext4 journal (stands for any
concurrent fsync)
python3 -c "import os; fd=os.open('$MNT/other', os.O_CREAT|os.O_WRONLY);
os.write(fd, b'x'); os.fsync(fd)"
# power cut: the device fails all further I/O, nothing is flushed first; then
"reboot"
dmsetup suspend --noflush --nolockfs cass
dmsetup load cass --table "0 $SECT error"; dmsetup resume cass
umount -l $MNT; sleep 1; dmsetup remove cass; losetup -d $LOOP
LOOP=$(losetup -f --show $IMG); mount $LOOP $MNT
od -c $MNT/data/ks/t-*/*_txn_compaction_*.log | tail -4 # COMMIT line
replaced by zeros
bin/cassandra -R -f # "Cannot remove
temporary or obsoleted files for ks.t ..."
{code}
Results (when=5, with the extra fsync): trunk 95b178a1 did not start in 5 of 9
runs, cassandra-5.0 dd48703a in 3 of 4 runs, always with the error above; in
the other runs the COMMIT line had reached the disk (the outcome depends on
whether the log's last data page is written out before the cut) and the node
recovered. The fsync-then-write order of every record was the same in every
run. Without a journal commit after the deletions (no extra fsync) the node
started in the run tried, because then neither the deletions nor the log's new
size were durable.
*Likely fix*
Flush the writer before forcing the channel in FileUtils.write (writer.flush(),
then SyncUtil.force), so that appendAndSync makes the record durable before it
returns. LogReplica.append relies on that for every record, and LogTransaction
deletes obsolete files right after the COMMIT append.
*Related*
- CASSANDRA-21649 (Review In Progress): REMOVE-record timestamp verification
fails after a crash during deletion of obsolete SSTables. Same start-up
refusal, different cause (deletion order); it does not change the missing sync
of the COMMIT record.
- CASSANDRA-18736 (fixed in 4.0.13): a streaming race leaves a corrupt
transaction log that prevents restart. Different cause.
- Regression from CASSANDRA-14134 (commit d6e508f33c1, 2018): before it,
FileUtils.write called Files.write(path, lines, CHARSET, options), which opens
the file with O_SYNC when SYNC is passed, so each record was durable when
write() returned. The patch replaced O_SYNC with "write all lines, then sync
once", but the sync runs before the BufferedWriter is flushed.
> Transaction log records are fsynced before they are written (FileUtils.write
> forces the channel before the BufferedWriter is flushed); a power loss after
> a compaction can leave the node unable to start
> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: CASSANDRA-21795
> URL: https://issues.apache.org/jira/browse/CASSANDRA-21795
> Project: Apache Cassandra
> Issue Type: Bug
> Components: Local/Compaction, Local/SSTable, Local/Startup and
> Shutdown
> Reporter: Ke Han
> Priority: Normal
>
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
