Ke Han created CASSANDRA-21794:
----------------------------------
Summary: Commit log replay after an interrupted DROP TABLE
discards whole mutations that also touched the dropped table (5.0: acknowledged
rows of other tables in the same logged batch are lost; trunk: the node does
not start)
Key: CASSANDRA-21794
URL: https://issues.apache.org/jira/browse/CASSANDRA-21794
Project: Apache Cassandra
Issue Type: Bug
Components: Local/Commit Log, Local/Startup and Shutdown
Reporter: Ke Han
Affects Version/s: 5.0.9, 5.0.x, 7.0 (trunk); by code inspection also 6.0 (same
CoordinatorBehindException path as trunk) and 4.1.x (same per-mutation skip as
5.0)
Environment: Single node, Linux 5.15 x86_64, ext4, OpenJDK 11, commitlog_sync:
batch, disk_failure_policy: stop (default). 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.
Description:
*What happens*
A logged batch that writes the same partition key to two tables of one keyspace
is stored as one Mutation per partition key, carrying a PartitionUpdate for
each table. DROP TABLE a calls ColumnFamilyStore.onTableDropped ->
CommitLog.forceRecycleAllSegments, which flushes every table with data in the
current segments, so normally the replay never needs those mutations again. If
that forced flush does not complete (an I/O error with disk_failure_policy:
stop, a crash, a power loss) while the drop itself has already been persisted,
the rows of the other table b exist only in the commit log, and the replay
handles the mixed mutations as a whole:
- cassandra-5.0: PartitionUpdate deserialization throws UnknownTableException
for a's update, CommitLogReader.readMutation catches it and skips the entire
mutation ("Skipped N mutations from unknown (probably removed) CF"), so the
acknowledged b rows in it are lost silently.
- trunk: the deserialization throws CoordinatorBehindException instead
(PartitionUpdate.serializer, lines 801-814: the local epoch is after the
mutation's epoch), which readMutation does not treat as an unknown table;
start-up stops with "Exiting due to error while processing commit log during
initialization". This happens for any leftover mutation of the dropped table,
not only mixed ones. With -Dcassandra.commitlog.ignorereplayerrors=true the
node starts and the mixed mutations are dropped, losing the b rows as on 5.0.
*Reproduce* (cqlsh and nodetool against a single node with commitlog_sync:
batch; strace >= 4.16, run as root or with ptrace permission)
{code:bash}
bin/cqlsh -e "
CREATE KEYSPACE ks WITH replication = \{'class': 'SimpleStrategy',
'replication_factor': 1};
CREATE TABLE ks.a (id int PRIMARY KEY, v text);
CREATE TABLE ks.b (id int PRIMARY KEY, v text);
BEGIN BATCH
INSERT INTO ks.a (id, v) VALUES (1, 'a1'); INSERT INTO ks.a (id, v) VALUES (2,
'a2'); INSERT INTO ks.a (id, v) VALUES (3, 'a3');
INSERT INTO ks.a (id, v) VALUES (4, 'a4'); INSERT INTO ks.a (id, v) VALUES (5,
'a5');
INSERT INTO ks.b (id, v) VALUES (1, 'b1'); INSERT INTO ks.b (id, v) VALUES (2,
'b2'); INSERT INTO ks.b (id, v) VALUES (3, 'b3');
INSERT INTO ks.b (id, v) VALUES (4, 'b4'); INSERT INTO ks.b (id, v) VALUES (5,
'b5'); INSERT INTO ks.b (id, v) VALUES (6, 'b6');
INSERT INTO ks.b (id, v) VALUES (7, 'b7'); INSERT INTO ks.b (id, v) VALUES (8,
'b8'); INSERT INTO ks.b (id, v) VALUES (9, 'b9');
INSERT INTO ks.b (id, v) VALUES (10, 'b10');
APPLY BATCH;
SELECT count(*) FROM ks.b;" # 10
# one EIO on the first fsync of b's table directory (the forced flush of b
creates its flush txn log there);
# use signal=KILL instead of error=EIO for a crash at the same point
BDIR=$(ls -d /var/lib/cassandra/data/ks/b-*)
strace -f -o /tmp/strace.log -e trace=fsync -e inject=fsync:error=EIO:when=1 -P
$BDIR -p $(pgrep -f CassandraDaemon) &
sleep 5
bin/cqlsh -e "DROP TABLE ks.a;" # FSWriteError, "Stopping transports as
disk_failure_policy is stop"
kill %1; kill -9 $(pgrep -f CassandraDaemon)
bin/cassandra # restart
bin/cqlsh -e "SELECT id, v FROM ks.b;"
{code}
*Actual*
cassandra-5.0 dd48703a (same with signal=KILL instead of EIO):
{noformat}
WARN [main] CommitLogReplayer.java:247 - Skipped 5 mutations from unknown
(probably removed) CF with id c76c6560-cb2e-11f1-af99-b54fecb308d4
INFO [main] CommitLog.java:210 - Log replay complete, 13 replayed mutations in
526 ms
id | v
----+-----
10 | b10
8 | b8
7 | b7
6 | b6
9 | b9
(5 rows)
{noformat}
Rows 1..5 of b, acknowledged by the batch long before the DROP, are gone.
Control: the same script with a's inserts using ids 101..105 (no shared
partition keys) also skips 5 mutations (a's own) and returns all 10 rows of b.
trunk 95b178a1 (EIO or SIGKILL at the same point; also with the ids 101..105
control):
{noformat}
ERROR [main] DefaultDiskErrorsHandler.java:177 - Exiting due to error while
processing commit log during initialization.
org.apache.cassandra.db.commitlog.CommitLogReadHandler$CommitLogReadException:
Unexpected error deserializing mutation; saved to
/tmp/mutation4107001581964003181dat. This may be caused by replaying a
mutation against a table with the same name but incompatible schema. Exception
follows: org.apache.cassandra.exceptions.CoordinatorBehindException: Couldn't
find table with id tid:4. If a table was just created, this is likely due to
the schema not being fully propagated. Please wait for schema agreement on
table creation.
at
org.apache.cassandra.db.commitlog.CommitLogReader.readMutation(CommitLogReader.java:472)
at
org.apache.cassandra.db.commitlog.CommitLogReader.readSection(CommitLogReader.java:405)
at
org.apache.cassandra.db.commitlog.CommitLogReader.readCommitLogSegment(CommitLogReader.java:251)
...
at org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:362)
{noformat}
The node does not start. Restarted with
-Dcassandra.commitlog.ignorereplayerrors=true it starts ("Ignoring commit log
replay error" for each mixed mutation) and SELECT returns only ids 6..10.
*Expected*
All 10 rows of b after the restart, and a node that starts. Mutations for a
table that was dropped after they were written are expected garbage; the replay
should skip only the PartitionUpdate of the dropped table and apply the rest of
the mutation (on trunk, a mutation older than the drop should be treated like
an unknown table during local replay, not as a coordinator that is behind).
*Code (trunk 95b178a1)*
- src/java/org/apache/cassandra/db/commitlog/CommitLogReader.java:446-458
catches UnknownTableException around Mutation.serializer.deserialize and
returns, dropping the whole mutation; any other exception goes to the
"Unexpected error deserializing mutation" path (460-480), which is fatal unless
ignorereplayerrors is set.
- src/java/org/apache/cassandra/db/Mutation.java:598-612 deserializes the
PartitionUpdates one by one; the first unknown table aborts the whole mutation.
- src/java/org/apache/cassandra/db/partitions/PartitionUpdate.java:801-814
turns UnknownTableException into CoordinatorBehindException when the local
epoch is after the mutation's epoch, which is what happens when replaying a
mutation written before the DROP (observed in every run).
- src/java/org/apache/cassandra/db/ColumnFamilyStore.java:3414 (onTableDropped)
is where the forced flush happens; nothing on start-up accounts for it not
having completed.
- cassandra-5.0 dd48703a: CommitLogReader.java:438 (catch
UnknownTableException), CommitLogReplayer.java:247 (the "Skipped ... probably
removed" warning).
*Related*
- CASSANDRA-1353 (fixed 2010): "commit log recovery is broken when the CL
contains mutations to CFs that have been dropped". The skipping that exists
today works per mutation, not per table.
- CASSANDRA-9179 (fixed): replay skips mutations of a dropped-and-recreated
table; by design for that table, it does not cover other tables in the same
mutation.
- CASSANDRA-16878 (Review In Progress): a race in commit log replay can cause
rejected mutations; different cause.
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
