[
https://issues.apache.org/jira/browse/CASSANDRA-11889?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15405609#comment-15405609
]
Stefania commented on CASSANDRA-11889:
--------------------------------------
CI is good, this can be reviewed.
> LogRecord: file system race condition may cause verify() to fail
> ----------------------------------------------------------------
>
> Key: CASSANDRA-11889
> URL: https://issues.apache.org/jira/browse/CASSANDRA-11889
> Project: Cassandra
> Issue Type: Bug
> Components: Local Write-Read Paths
> Reporter: Stefania
> Assignee: Stefania
> Fix For: 3.0.x, 3.x
>
>
> The following exception was reported in CASSANDRA-11470. It occurred whilst
> listing files with compaction in progress:
> {code}
> 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
> {code}
> The error of interest is:
> {code}
> 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]
> {code}
> The problem is this code here in LogRecord:
> {code}
> 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()));
> }
> {code}
> 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:
> {code}
> 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));
> }
> {code}
> 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.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
