[jira] [Created] (CASSANDRA-21795) 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

["Ke Han (Jira)" <ji...@apache.org>]

Ke Han created CASSANDRA-21795:
----------------------------------

             Summary: 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


 
*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.
 



--
This message was sent by Atlassian Jira
(v10.3.26#10030026)

---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@cassandra.apache.org
For additional commands, e-mail: commits-help@cassandra.apache.org