Cassandra
  1. Cassandra
  2. CASSANDRA-4832

AssertionError: keys must not be empty

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Minor Minor
    • Resolution: Fixed
    • Fix Version/s: 1.1.7
    • Component/s: Core
    • Labels:
    • Environment:

      Debian 6.0.5

      Description

      I'm getting errors like this logged:

      INFO 07:08:32,104 Compacting [SSTableReader(path='/var/lib/cassandra/data/Fusion/quoteinfo/Fusion-quoteinfo.quoteinfo_search_value_idx-hf-114-Data.db'), SSTableReader(path='/var/lib/cassandra/data/Fusion/quoteinfo/Fusion-quoteinfo.quoteinfo_search_value_idx-hf-113-Data.db'), SSTableReader(path='/var/lib/cassandra/data/Fusion/quoteinfo/Fusion-quoteinfo.quoteinfo_search_value_idx-hf-110-Data.db'), SSTableReader(path='/var/lib/cassandra/data/Fusion/quoteinfo/Fusion-quoteinfo.quoteinfo_search_value_idx-hd-108-Data.db'), SSTableReader(path='/var/lib/cassandra/data/Fusion/quoteinfo/Fusion-quoteinfo.quoteinfo_search_value_idx-hd-106-Data.db'), SSTableReader(path='/var/lib/cassandra/data/Fusion/quoteinfo/Fusion-quoteinfo.quoteinfo_search_value_idx-hd-107-Data.db'), SSTableReader(path='/var/lib/cassandra/data/Fusion/quoteinfo/Fusion-quoteinfo.quoteinfo_search_value_idx-hf-112-Data.db'), SSTableReader(path='/var/lib/cassandra/data/Fusion/quoteinfo/Fusion-quoteinfo.quoteinfo_search_value_idx-hf-109-Data.db'), SSTableReader(path='/var/lib/cassandra/data/Fusion/quoteinfo/Fusion-quoteinfo.quoteinfo_search_value_idx-hf-111-Data.db')]
      ERROR 07:08:32,108 Exception in thread Thread[CompactionExecutor:5,1,main]
      java.lang.AssertionError: Keys must not be empty
      at org.apache.cassandra.io.sstable.SSTableWriter.beforeAppend(SSTableWriter.java:133)
      at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:154)
      at org.apache.cassandra.db.compaction.CompactionTask.execute(CompactionTask.java:159)
      at org.apache.cassandra.db.compaction.CompactionManager$1.runMayThrow(CompactionManager.java:154)
      at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:662)

      I'm not really sure when this started happening; they tend to be logged during a repair but I can't reproduce the error 100% reliably.

        Issue Links

          Activity

          Tristan Seligmann created issue -
          Hide
          Tristan Seligmann added a comment -

          Actually, it seems like this gets logged any time Cassandra tries to flush this column family now.

          Show
          Tristan Seligmann added a comment - Actually, it seems like this gets logged any time Cassandra tries to flush this column family now.
          Hide
          Tristan Seligmann added a comment -

          After some further investigation, it looks like this began after I upgraded from 1.1.2 to 1.1.6. The assertion seems to have been introduced as part of some debugging in CASSANDRA-4687. I'm not familiar with the code at all, but it seems to me that perhaps the assertion is bogus? If I have a secondary index on a particular column, and that column has an empty value in some row, would this not result in an empty key in the secondary index column family?

          Show
          Tristan Seligmann added a comment - After some further investigation, it looks like this began after I upgraded from 1.1.2 to 1.1.6. The assertion seems to have been introduced as part of some debugging in CASSANDRA-4687 . I'm not familiar with the code at all, but it seems to me that perhaps the assertion is bogus? If I have a secondary index on a particular column, and that column has an empty value in some row, would this not result in an empty key in the secondary index column family?
          Hide
          Tristan Seligmann added a comment -

          I modified my application to avoid inserting the empty column in question (which was a bug anyway; if that particular column was empty, the application should not have been doing an insert at all) and the problem has gone away, so it seems like my hypothesis is at least partially correct. I'm going to attempt to reproduce this in a more controlled environment now that my immediate issue in production has been resolved.

          Show
          Tristan Seligmann added a comment - I modified my application to avoid inserting the empty column in question (which was a bug anyway; if that particular column was empty, the application should not have been doing an insert at all) and the problem has gone away, so it seems like my hypothesis is at least partially correct. I'm going to attempt to reproduce this in a more controlled environment now that my immediate issue in production has been resolved.
          Hide
          Jonathan Ellis added a comment - - edited

          you're right that the assert is bogus. removed it in 72dcc298d335721c053444249c157e9a6431ebea.

          Show
          Jonathan Ellis added a comment - - edited you're right that the assert is bogus. removed it in 72dcc298d335721c053444249c157e9a6431ebea.
          Jonathan Ellis made changes -
          Field Original Value New Value
          Labels indexing
          Assignee Tristan Seligmann [ mithrandi ]
          Fix Version/s 1.1.7 [ 12323354 ]
          Priority Major [ 3 ] Minor [ 4 ]
          Component/s Core [ 12312978 ]
          Reviewer jbellis
          Hide
          Chris Herron added a comment -

          Came across this investigating an apparent deadlock in Schema Migrations.

          If this assertion fails on the flushWriter executor, it blocks indefinitely. Anything upstream locking-wise gets stuck also. This was on 1.1.6.

          Log output below, thread dump attached.

          ERROR [FlushWriter:3] 2012-10-19 22:27:56,948 org.apache.cassandra.service.AbstractCassandraDaemon Exception in thread Thread[FlushWriter:3,5,main]
          java.lang.AssertionError: Keys must not be empty
          at org.apache.cassandra.io.sstable.SSTableWriter.beforeAppend(SSTableWriter.java:133)
          at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:176)
          at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:295)
          at org.apache.cassandra.db.Memtable.access$600(Memtable.java:48)
          at org.apache.cassandra.db.Memtable$5.runMayThrow(Memtable.java:316)
          at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)
          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
          at java.lang.Thread.run(Thread.java:662)

          Show
          Chris Herron added a comment - Came across this investigating an apparent deadlock in Schema Migrations. If this assertion fails on the flushWriter executor, it blocks indefinitely. Anything upstream locking-wise gets stuck also. This was on 1.1.6. Log output below, thread dump attached. ERROR [FlushWriter:3] 2012-10-19 22:27:56,948 org.apache.cassandra.service.AbstractCassandraDaemon Exception in thread Thread [FlushWriter:3,5,main] java.lang.AssertionError: Keys must not be empty at org.apache.cassandra.io.sstable.SSTableWriter.beforeAppend(SSTableWriter.java:133) at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:176) at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:295) at org.apache.cassandra.db.Memtable.access$600(Memtable.java:48) at org.apache.cassandra.db.Memtable$5.runMayThrow(Memtable.java:316) at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662)
          Chris Herron made changes -
          Attachment FlushWriterKeyAssertionBlock.txt [ 12550155 ]
          Joe Fox made changes -
          Comment [ I'm seeing the same issue as Chris after updating from 1.1.1 to 1.1.6. ]
          Hide
          Joe Fox added a comment - - edited

          I've run into the same symptoms as Chris, but while attempting to migrate data between a 1.1.1 cluster and 1.1.6.

          Whilst using sstableloader to import the data, nodes would hit certain column indexes and stop processing further requests once the assertion was thrown - restarting the node would almost immediately throw the assertion again, and the node would just fail to rejoin the ring.

          tpstats would show active flushwriter tasks but no further node activity.

          We had to work around the issue by:

          1. Removing all indexes from our target cluster schema
          2. Importing the data via sstableloader
          3. Scanning through relevant column families and inserting data into any empty indexed columns
          4. Re-applying the indexes to the target cluster schema

          Only then was the migration successful.

          I'll also note that attempting to apply an index to a column which has null data will also throw the cluster out of sync as the nodes which throw the assertion fail to migrate their schemas properly

          INFO [Creating index: Transactions.TransactionsCountryCode] 2012-10-21 07:45:25,978 ColumnFamilyStore.java (line 659) Enqueuing flush of Memtable-Transactions.TransactionsCountryCode@1802367190(38862/169512 serialized/live bytes, 762 ops)
          INFO [Creating index: Transactions.TransactionsStatus] 2012-10-21 07:45:25,980 ColumnFamilyStore.java (line 659) Enqueuing flush of Memtable-Transactions.TransactionsStatus@673679943(38862/125966 serialized/live bytes, 762 ops)
          INFO [FlushWriter:1] 2012-10-21 07:45:25,987 Memtable.java (line 264) Writing Memtable-Transactions.TransactionsCountryCode@1802367190(38862/169512 serialized/live bytes, 762 ops)
          INFO [FlushWriter:2] 2012-10-21 07:45:26,004 Memtable.java (line 264) Writing Memtable-Transactions.TransactionsStatus@673679943(38862/125966 serialized/live bytes, 762 ops)
          ERROR [FlushWriter:1] 2012-10-21 07:45:26,004 AbstractCassandraDaemon.java (line 135) Exception in thread Thread[FlushWriter:1,5,main]
          java.lang.AssertionError: Keys must not be empty
          at org.apache.cassandra.io.sstable.SSTableWriter.beforeAppend(SSTableWriter.java:133)
          at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:176)
          at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:295)
          at org.apache.cassandra.db.Memtable.access$600(Memtable.java:48)
          at org.apache.cassandra.db.Memtable$5.runMayThrow(Memtable.java:316)
          at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)
          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
          at java.lang.Thread.run(Thread.java:662)
          INFO [FlushWriter:2] 2012-10-21 07:45:26,049 Memtable.java (line 305) Completed flushing /var/lib/cassandra/data/xxxxxx/Transactions/xxxxxx-Transactions.TransactionsStatus-hf-2-Data.db (35259 bytes) for commitlog position ReplayPosition(segmentId=1350805525722, position=0)
          INFO [Creating index: Transactions.TransactionsLastUpdateDate] 2012-10-21 07:45:26,313 ColumnFamilyStore.java (line 659) Enqueuing flush of Memtable-Transactions.TransactionsLastUpdateDate@1912098049(38862/240277 serialized/live bytes, 762 ops)
          INFO [FlushWriter:2] 2012-10-21 07:45:26,314 Memtable.java (line 264) Writing Memtable-Transactions.TransactionsLastUpdateDate@1912098049(38862/240277 serialized/live bytes, 762 ops)
          INFO [FlushWriter:2] 2012-10-21 07:45:26,743 Memtable.java (line 305) Completed flushing /var/lib/cassandra/data/xxxxxx/Transactions/xxxxxx-Transactions.TransactionsLastUpdateDate-hf-2-Data.db (37024 bytes) for commitlog position ReplayPosition(segmentId=1350805525722, position=0)
          INFO [main] 2012-10-21 07:45:27,052 CommitLogReplayer.java (line 272) Finished reading /var/lib/cassandra/commitlog/CommitLog-1350768744805.log
          INFO [main] 2012-10-21 07:45:27,054 ColumnFamilyStore.java (line 659) Enqueuing flush of Memtable-Versions@1851630436(83/103 serialized/live bytes, 3 ops)
          INFO [FlushWriter:2] 2012-10-21 07:45:27,054 Memtable.java (line 264) Writing Memtable-Versions@1851630436(83/103 serialized/live bytes, 3 ops)
          INFO [FlushWriter:2] 2012-10-21 07:45:27,061 Memtable.java (line 305) Completed flushing /var/lib/cassandra/data/system/Versions/system-Versions-hf-1-Data.db (247 bytes) for commitlog position ReplayPosition(segmentId=1350805525722, position=0)

          Show
          Joe Fox added a comment - - edited I've run into the same symptoms as Chris, but while attempting to migrate data between a 1.1.1 cluster and 1.1.6. Whilst using sstableloader to import the data, nodes would hit certain column indexes and stop processing further requests once the assertion was thrown - restarting the node would almost immediately throw the assertion again, and the node would just fail to rejoin the ring. tpstats would show active flushwriter tasks but no further node activity. We had to work around the issue by: 1. Removing all indexes from our target cluster schema 2. Importing the data via sstableloader 3. Scanning through relevant column families and inserting data into any empty indexed columns 4. Re-applying the indexes to the target cluster schema Only then was the migration successful. I'll also note that attempting to apply an index to a column which has null data will also throw the cluster out of sync as the nodes which throw the assertion fail to migrate their schemas properly INFO [Creating index: Transactions.TransactionsCountryCode] 2012-10-21 07:45:25,978 ColumnFamilyStore.java (line 659) Enqueuing flush of Memtable-Transactions.TransactionsCountryCode@1802367190(38862/169512 serialized/live bytes, 762 ops) INFO [Creating index: Transactions.TransactionsStatus] 2012-10-21 07:45:25,980 ColumnFamilyStore.java (line 659) Enqueuing flush of Memtable-Transactions.TransactionsStatus@673679943(38862/125966 serialized/live bytes, 762 ops) INFO [FlushWriter:1] 2012-10-21 07:45:25,987 Memtable.java (line 264) Writing Memtable-Transactions.TransactionsCountryCode@1802367190(38862/169512 serialized/live bytes, 762 ops) INFO [FlushWriter:2] 2012-10-21 07:45:26,004 Memtable.java (line 264) Writing Memtable-Transactions.TransactionsStatus@673679943(38862/125966 serialized/live bytes, 762 ops) ERROR [FlushWriter:1] 2012-10-21 07:45:26,004 AbstractCassandraDaemon.java (line 135) Exception in thread Thread [FlushWriter:1,5,main] java.lang.AssertionError: Keys must not be empty at org.apache.cassandra.io.sstable.SSTableWriter.beforeAppend(SSTableWriter.java:133) at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:176) at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:295) at org.apache.cassandra.db.Memtable.access$600(Memtable.java:48) at org.apache.cassandra.db.Memtable$5.runMayThrow(Memtable.java:316) at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) INFO [FlushWriter:2] 2012-10-21 07:45:26,049 Memtable.java (line 305) Completed flushing /var/lib/cassandra/data/xxxxxx/Transactions/xxxxxx-Transactions.TransactionsStatus-hf-2-Data.db (35259 bytes) for commitlog position ReplayPosition(segmentId=1350805525722, position=0) INFO [Creating index: Transactions.TransactionsLastUpdateDate] 2012-10-21 07:45:26,313 ColumnFamilyStore.java (line 659) Enqueuing flush of Memtable-Transactions.TransactionsLastUpdateDate@1912098049(38862/240277 serialized/live bytes, 762 ops) INFO [FlushWriter:2] 2012-10-21 07:45:26,314 Memtable.java (line 264) Writing Memtable-Transactions.TransactionsLastUpdateDate@1912098049(38862/240277 serialized/live bytes, 762 ops) INFO [FlushWriter:2] 2012-10-21 07:45:26,743 Memtable.java (line 305) Completed flushing /var/lib/cassandra/data/xxxxxx/Transactions/xxxxxx-Transactions.TransactionsLastUpdateDate-hf-2-Data.db (37024 bytes) for commitlog position ReplayPosition(segmentId=1350805525722, position=0) INFO [main] 2012-10-21 07:45:27,052 CommitLogReplayer.java (line 272) Finished reading /var/lib/cassandra/commitlog/CommitLog-1350768744805.log INFO [main] 2012-10-21 07:45:27,054 ColumnFamilyStore.java (line 659) Enqueuing flush of Memtable-Versions@1851630436(83/103 serialized/live bytes, 3 ops) INFO [FlushWriter:2] 2012-10-21 07:45:27,054 Memtable.java (line 264) Writing Memtable-Versions@1851630436(83/103 serialized/live bytes, 3 ops) INFO [FlushWriter:2] 2012-10-21 07:45:27,061 Memtable.java (line 305) Completed flushing /var/lib/cassandra/data/system/Versions/system-Versions-hf-1-Data.db (247 bytes) for commitlog position ReplayPosition(segmentId=1350805525722, position=0)
          Jonathan Ellis made changes -
          Status Open [ 1 ] Resolved [ 5 ]
          Resolution Fixed [ 1 ]
          Hide
          Scott Fines added a comment -

          Is there an actual patch for this, or a Workaround? We see this same AssertionError when attempting to start our nodes; restarting the node usually works correctly, however.

          Show
          Scott Fines added a comment - Is there an actual patch for this, or a Workaround? We see this same AssertionError when attempting to start our nodes; restarting the node usually works correctly, however.
          Hide
          Jonathan Ellis added a comment -

          The patch to fix this is git commit 72dcc298d335721c053444249c157e9a6431ebea.

          Show
          Jonathan Ellis added a comment - The patch to fix this is git commit 72dcc298d335721c053444249c157e9a6431ebea.
          Jeremy Hanna made changes -
          Link This issue is duplicated by CASSANDRA-4991 [ CASSANDRA-4991 ]
          Gavin made changes -
          Workflow no-reopen-closed, patch-avail [ 12730282 ] patch-available, re-open possible [ 12753534 ]
          Gavin made changes -
          Workflow patch-available, re-open possible [ 12753534 ] reopen-resolved, no closed status, patch-avail, testing [ 12758791 ]

            People

            • Assignee:
              Tristan Seligmann
              Reporter:
              Tristan Seligmann
              Reviewer:
              Jonathan Ellis
            • Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development