Details
-
Bug
-
Status: Resolved
-
Normal
-
Resolution: Fixed
-
None
-
Normal
Description
The following exception was reported in CASSANDRA-11470. It occurred whilst listing files with compaction in progress:
WARN [CompactionExecutor:2006] 2016-05-23 18:23:31,694 BigTableWriter.java:171 - Writing large partition test_keyspace/test_columnfamily:eda6b9c36f8df6fe596492c3438d7a38e9b109a6 (123663388 bytes) INFO [IndexSummaryManager:1] 2016-05-23 18:24:23,731 IndexSummaryRedistribution.java:74 - Redistributing index summaries WARN [CompactionExecutor:2006] 2016-05-23 18:24:56,669 BigTableWriter.java:171 - Writing large partition test_keyspace/test_columnfamily:05b6b424194dd19ab7cfbcd53c4979768cd859e9 (256286063 bytes) WARN [CompactionExecutor:2006] 2016-05-23 18:26:23,575 BigTableWriter.java:171 - Writing large partition test_keyspace/test_columnfamily:04e9fac15552b9ae77c27a6cb8d0fd11fdcc24d7 (212445557 bytes) INFO [CompactionExecutor:2005] 2016-05-23 18:29:26,839 LeveledManifest.java:437 - Adding high-level (L3) BigTableReader(path='/data/cassandra/data/test_keyspace/test_columnfamily_2-d29dd71045a811e59aff6776bf484396/ma-61041-big-Data.db') to candidates WARN [CompactionExecutor:2006] 2016-05-23 18:30:34,154 BigTableWriter.java:171 - Writing large partition test_keyspace/test_columnfamily:edbe6f178503be90911dbf29a55b97a4b095a9ec (183852539 bytes) INFO [CompactionExecutor:2006] 2016-05-23 18:31:21,080 LeveledManifest.java:437 - Adding high-level (L3) BigTableReader(path='/data/cassandra/data/test_keyspace/test_columnfamily_2-d29dd71045a811e59aff6776bf484396/ma-61042-big-Data.db') to candidates ERROR [metrics-graphite-reporter-1-thread-1] 2016-05-23 18:31:21,207 LogFile.java:173 - Unexpected files detected for sstable [ma-91034-big], record [REMOVE:[/data/cassandra/data/test_keyspace/test_columnfamily-3996ce80b7ac11e48a9b6776bf484396/ma-91034-big,1463992176000,8][457420186]]: last update time [00:00:00] should have been [08:29:36] ERROR [metrics-graphite-reporter-1-thread-1] 2016-05-23 18:31:21,208 ScheduledReporter.java:119 - RuntimeException thrown from GraphiteReporter#report. Exception was suppressed. java.lang.RuntimeException: Failed to list files in /data/cassandra/data/test_keyspace/test_columnfamily-3996ce80b7ac11e48a9b6776bf484396 at org.apache.cassandra.db.lifecycle.LogAwareFileLister.list(LogAwareFileLister.java:57) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.db.lifecycle.LifecycleTransaction.getFiles(LifecycleTransaction.java:547) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.db.Directories$SSTableLister.filter(Directories.java:691) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.db.Directories$SSTableLister.listFiles(Directories.java:662) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.db.Directories$TrueFilesSizeVisitor.<init>(Directories.java:981) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.db.Directories.getTrueAllocatedSizeIn(Directories.java:893) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.db.Directories.trueSnapshotsSize(Directories.java:883) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.db.ColumnFamilyStore.trueSnapshotsSize(ColumnFamilyStore.java:2332) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.metrics.TableMetrics$32.getValue(TableMetrics.java:637) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.metrics.TableMetrics$32.getValue(TableMetrics.java:634) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.metrics.TableMetrics$33.getValue(TableMetrics.java:692) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.metrics.TableMetrics$33.getValue(TableMetrics.java:686) ~[apache-cassandra-3.0.6.jar:3.0.6] at com.codahale.metrics.graphite.GraphiteReporter.reportGauge(GraphiteReporter.java:281) ~[metrics-graphite-3.1.0.jar:3.1.0] at com.codahale.metrics.graphite.GraphiteReporter.report(GraphiteReporter.java:158) ~[metrics-graphite-3.1.0.jar:3.1.0] at com.codahale.metrics.ScheduledReporter.report(ScheduledReporter.java:162) ~[metrics-core-3.1.0.jar:3.1.0] at com.codahale.metrics.ScheduledReporter$1.run(ScheduledReporter.java:117) ~[metrics-core-3.1.0.jar:3.1.0] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [na:1.8.0_91] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_91] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [na:1.8.0_91] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91] at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91] Caused by: org.apache.cassandra.db.lifecycle.LogTransaction$CorruptTransactionLogException: Some records failed verification. See earlier in log for details. at org.apache.cassandra.db.lifecycle.LogAwareFileLister.readTxnLog(LogAwareFileLister.java:114) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.db.lifecycle.LogAwareFileLister.classifyFiles(LogAwareFileLister.java:106) ~[apache-cassandra-3.0.6.jar:3.0.6] at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) ~[na:1.8.0_91] at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) ~[na:1.8.0_91] at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1374) ~[na:1.8.0_91] at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) ~[na:1.8.0_91] at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) ~[na:1.8.0_91] at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) ~[na:1.8.0_91] at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) ~[na:1.8.0_91] at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[na:1.8.0_91] at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418) ~[na:1.8.0_91] at org.apache.cassandra.db.lifecycle.LogAwareFileLister.innerList(LogAwareFileLister.java:75) ~[apache-cassandra-3.0.6.jar:3.0.6] at org.apache.cassandra.db.lifecycle.LogAwareFileLister.list(LogAwareFileLister.java:53) ~[apache-cassandra-3.0.6.jar:3.0.6] ... 22 common frames omitted INFO [CompactionExecutor:2005] 2016-05-23 18:32:27,284 LeveledManifest.java:437 - Adding high-level (L3) BigTableReader(path='/data/cassandra/data/test_keyspace/test_columnfamily_3-37a9cb90b7ac11e48a9b6776bf484396/ma-98189-big-Data.db') to candidates INFO [CompactionExecutor:2005] 2016-05-23 18:34:42,562 LeveledManifest.java:437 - Adding high-level (L3) BigTableReader(path='/data/cassandra/data/test_keyspace/test_columnfamily_3-37a9cb90b7ac11e48a9b6776bf484396/ma-98210-big-Data.db') to candidates
The error of interest is:
ERROR [metrics-graphite-reporter-1-thread-1] 2016-05-23 18:31:21,207 LogFile.java:173 - Unexpected files detected for sstable [ma-91034-big], record [REMOVE:[/data/cassandra/data/test_keyspace/test_columnfamily-3996ce80b7ac11e48a9b6776bf484396/ma-91034-big,1463992176000,8][457420186]]: last update time [00:00:00] should have been [08:29:36]
The problem is this code here in LogRecord:
public LogRecord withExistingFiles() { return make(type, getExistingFiles(), 0, absolutePath.get()); } public static LogRecord make(Type type, List<File> files, int minFiles, String absolutePath) { long lastModified = files.stream().map(File::lastModified).reduce(0L, Long::max); return new LogRecord(type, absolutePath, lastModified, Math.max(minFiles, files.size())); }
If the sstable files are completely deleted after getExistingFiles() has returned them and before lastModified is calculated, then we may report last update time as zero because the files no longer exist and still indicate that there are files on disk so that this code in LogFile.verifyRecord fails:
record.status.onDiskRecord = record.withExistingFiles();
if (record.updateTime != record.status.onDiskRecord.updateTime && record.status.onDiskRecord.numFiles > 0)
{
record.setError(String.format("Unexpected files detected for sstable [%s], " +
"record [%s]: last update time [%tT] should have been [%tT]",
record.fileName(),
record,
record.status.onDiskRecord.updateTime,
record.updateTime));
}
As a consequence, we throw an exception when listing files. In this case we were calculating the true snapshot size for the metrics.
Note that we are careful to delete files from oldest to newest so that the last update time should always match what is stored in the txn log, however if all files are deleted then we report last update time as zero. So, if my analysis is correct, this problem should not be very frequent.