[CASSANDRA-9862] Missing sstable files seen some time after the same file is logged as being part of a compaction

• Type: Bug
• Status: Open
• Priority: Normal
• Resolution: Unresolved
• Component/s: Local/Compaction
• Severity: Normal
• Assignee: Unassigned
• Reporter: Mark Curtis
• Created: 22/Jul/15 10:21
• Updated: 16/Apr/19 09:31

Description

The system will sometimes see a file not found exception in a given node’s logs. This is seen after the same file appears in a compaction statement either earlier on in the logs. I found the following events of potential interest:

I pulled out the missing files using this command:

grep "Caused by: java.io.FileNotFoundException:" * | awk '{print $4}' | sort -u > files-to-search

Using the following file as an example: my_keyspace-my_table-jb-2085190-Data.db

File is created from a flush

system.log.10

   7549  INFO [FlushWriter:1] 2015-06-03 12:25:31,857 Memtable.java (line 395) Completed flushing /raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.d   7549 b (66804 bytes) for commitlog position ReplayPosition(segmentId=1433333700832, position=2479196)

Next it appears in a compaction

system.log.10

   8758  INFO [CompactionExecutor:5] 2015-06-03 12:25:37,209 CompactionTask.java (line 115) Compacting [SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084993-Data.db'), SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085164-Data.db'), 
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.db'), SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-...
...<truncated>...

The next time we see the file its in file not found exceptions

system.log.9
  53811 java.lang.RuntimeException: java.io.FileNotFoundException: /raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.db (No such file or directory)

So going back to compaction executor 5 in system.log.10

   9102  INFO [CompactionExecutor:5] 2015-06-03 12:25:38,684 ColumnFamilyStore.java (line 794) Enqueuing flush of Memtable-compactions_in_progress@1431151640(0/0 serialized/live bytes, 1 ops)
...
   9107  INFO [CompactionExecutor:5] 2015-06-03 12:25:38,701 CompactionTask.java (line 287) Compacted 32 sstables to [/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-data_my_table-jb-2085196,].  1,970,986 bytes to 1,880,866 (~95% of original) in 1,492ms = 1.202234MB/s.  13,576 total partitions merged to 11,243.  Partition merge counts were {1:9379, 2:1474, 3:324, 4:54   9107 , 5:11, 6:1, }
   9108  INFO [CompactionExecutor:5] 2015-06-03 12:25:38,702 ColumnFamilyStore.java (line 794) Enqueuing flush of Memtable-compactions_in_progress@493376470(357/3570 serialized/live bytes, 16 ops)
...
    9111  INFO [CompactionExecutor:5] 2015-06-03 12:25:38,717 CompactionTask.java (line 115) Compacting [SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085182-Data.db'), SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085192-Data.db'), SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085175-Data.db'), SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085196-Data.db'), SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085194-Data.db'), 
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085191-Data.db'), SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085193-Data.db'), SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085195-Data.db'), 
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084985-Data.db'), SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085114-Data.db'), SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084901-Data.db')]
   9112 ERROR [CompactionExecutor:5] 2015-06-03 12:25:38,718 CassandraDaemon.java (line 199) Exception in thread Thread[CompactionExecutor:5,1,main]
   9113 java.lang.RuntimeException: java.io.FileNotFoundException: /raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084901-Data.db (No such file or directory)

So could it be that because the thread "CompactionExecutor:5" hit an exception in line 9113 that the compaction in 8758 didn't complete?