Cassandra
  1. Cassandra
  2. CASSANDRA-4078

StackOverflowError when upgrading to 1.0.8 from 0.8.10

    Details

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

      OS: Linux xps.openfin 2.6.35.13-91.fc14.i686 #1 SMP Tue May 3 13:36:36 UTC 2011 i686 i686 i386 GNU/Linux

      Java: JVM vendor/version: Java HotSpot(TM) Server VM/1.6.0_31

      Description

      Hello

      I am trying to upgrade our 1-node setup from 0.8.10 to 1.0.8 and seeing the following exception when starting up 1.0.8. We have been running 0.8.10 without any issues.

      Attached is the entire log file during startup of 1.0.8. There are 2 exceptions:

      1. StackOverflowError (line 2599)
      2. InstanceAlreadyExistsException (line 3632)

      I tried "run scrub" under 0.8.10 first, it did not help. Also, I tried dropping the column family which caused the exception, it just got the same exceptions from another column family.

      Thanks

      1. system.log
        765 kB
        Wenjun
      2. 4078.add-asserts.txt
        2 kB
        paul cannon
      3. system.log.0326
        2.96 MB
        Wenjun
      4. system.log.0326-02
        565 kB
        Wenjun
      5. cassandra.yaml.1.0.8
        19 kB
        Wenjun
      6. cassandra.yaml.8.10
        18 kB
        Wenjun
      7. keycheck.txt
        7 kB
        Wenjun
      8. 4078.patch2.txt
        3 kB
        paul cannon
      9. 4078-asserts-v3.txt
        4 kB
        Jonathan Ellis

        Activity

        Hide
        Wenjun added a comment -

        startup log from version 1.0.8

        Show
        Wenjun added a comment - startup log from version 1.0.8
        Hide
        Jonathan Ellis added a comment -

        Looks like a problem w/ the intervaltree creation.

        Show
        Jonathan Ellis added a comment - Looks like a problem w/ the intervaltree creation.
        Hide
        paul cannon added a comment -

        Wenjun, would it be possible to run your 1.0.8 version again (with DEBUG logging, as before) with this patch applied?

        I haven't been able to figure out yet how this could get into an infinite recursion, but if we can identify an invalid assumption somewhere, that ought to help a lot.

        If it's easier to get at, this change is also available in my github fork at git@github.com:thepaul/cassandra.git (branch named 4078).

        Show
        paul cannon added a comment - Wenjun, would it be possible to run your 1.0.8 version again (with DEBUG logging, as before) with this patch applied? I haven't been able to figure out yet how this could get into an infinite recursion, but if we can identify an invalid assumption somewhere, that ought to help a lot. If it's easier to get at, this change is also available in my github fork at git@github.com:thepaul/cassandra.git (branch named 4078).
        Hide
        Wenjun added a comment -

        Paul
        when I tried running code from git@github.com:thepaul/cassandra.git and I am getting the following errors. The only changes I made in cassandra.yaml are path to data files and local IP address.

        java.lang.RuntimeException: org.apache.cassandra.config.ConfigurationException: SimpleStrategy requires a replication_factor strategy option.

        I don't really use git so I may have done something wrong to get your code. The command I used is "git clone git@github.com:thepaul/cassandra.git". I noticed your changes in IntervalNode.java were not included in the cloned code. I copied the changes from 4078.add-aserts.txt. ant was able to build without any issues. How do I make sure the new classe files are included in cassandra runtime?

        Attached is the complete log for startup.

        Thanks
        Wenjun

        Show
        Wenjun added a comment - Paul when I tried running code from git@github.com:thepaul/cassandra.git and I am getting the following errors. The only changes I made in cassandra.yaml are path to data files and local IP address. java.lang.RuntimeException: org.apache.cassandra.config.ConfigurationException: SimpleStrategy requires a replication_factor strategy option. I don't really use git so I may have done something wrong to get your code. The command I used is "git clone git@github.com:thepaul/cassandra.git". I noticed your changes in IntervalNode.java were not included in the cloned code. I copied the changes from 4078.add-aserts.txt. ant was able to build without any issues. How do I make sure the new classe files are included in cassandra runtime? Attached is the complete log for startup. Thanks Wenjun
        Hide
        paul cannon added a comment -

        Ah, you got trunk by default (unstable code for future Cassandra 1.2). You need to do "git checkout 4078" in that directory to switch to the 4078 branch.

        Show
        paul cannon added a comment - Ah, you got trunk by default (unstable code for future Cassandra 1.2). You need to do "git checkout 4078" in that directory to switch to the 4078 branch.
        Hide
        Wenjun added a comment -

        I am able to download the branch from github site. Attached is the log file.

        Thanks

        Show
        Wenjun added a comment - I am able to download the branch from github site. Attached is the log file. Thanks
        Hide
        paul cannon added a comment -

        Ok. It looks like there are indeed 6 places where something is trying to create an Interval where the min is greater than the max. The following are taken from your log, right before the AssertionError, with some spaces added and other valid intervals cut out:

        Interval(DecoratedKey(f3f31fef-9b24-4fe3-be8e-b54a43ccf867, f3f31fef9b244fe3be8eb54a43ccf867),
                 DecoratedKey(62476171-4693-4a81-bd7c-01726bfca4c1, 6247617146934a81bd7c01726bfca4c1)),
        Interval(DecoratedKey(c60e0fbc-dcc6-472c-8d5c-8b3cd041e4c9, c60e0fbcdcc6472c8d5c8b3cd041e4c9),
                 DecoratedKey(7dd77e1f-92e0-4bc7-a417-2f9b0b97170d, 7dd77e1f92e04bc7a4172f9b0b97170d)),
        Interval(DecoratedKey(920c1919-98c4-4da8-88da-325067f9ece3, 920c191998c44da888da325067f9ece3),
                 DecoratedKey(40d6f31d-4b37-492e-b06c-9de0088de83f, 40d6f31d4b37492eb06c9de0088de83f)),
        Interval(DecoratedKey(a5f8d3d8-d26a-47fd-904c-8d55784776fc, a5f8d3d8d26a47fd904c8d55784776fc),
                 DecoratedKey(762f9402-e5f6-44bb-824c-f93170c2f508, 762f9402e5f644bb824cf93170c2f508)),
        Interval(DecoratedKey(a27d2f3b-8255-42fb-a8d5-5f0fe488dadb, a27d2f3b825542fba8d55f0fe488dadb),
                 DecoratedKey(7582809c-34b3-4736-8dfe-19811303bbfa, 7582809c34b347368dfe19811303bbfa)),
        Interval(DecoratedKey(d72c5963-ebe8-4e13-a74b-5584ca1d053c, d72c5963ebe84e13a74b5584ca1d053c),
                 DecoratedKey(4962307f-261d-469a-b48b-1de7cd7a7700, 4962307f261d469ab48b1de7cd7a7700)),
        

        This shouldn't ever happen, so I'll do some poking around to see where these come from.

        Show
        paul cannon added a comment - Ok. It looks like there are indeed 6 places where something is trying to create an Interval where the min is greater than the max. The following are taken from your log, right before the AssertionError, with some spaces added and other valid intervals cut out: Interval(DecoratedKey(f3f31fef-9b24-4fe3-be8e-b54a43ccf867, f3f31fef9b244fe3be8eb54a43ccf867), DecoratedKey(62476171-4693-4a81-bd7c-01726bfca4c1, 6247617146934a81bd7c01726bfca4c1)), Interval(DecoratedKey(c60e0fbc-dcc6-472c-8d5c-8b3cd041e4c9, c60e0fbcdcc6472c8d5c8b3cd041e4c9), DecoratedKey(7dd77e1f-92e0-4bc7-a417-2f9b0b97170d, 7dd77e1f92e04bc7a4172f9b0b97170d)), Interval(DecoratedKey(920c1919-98c4-4da8-88da-325067f9ece3, 920c191998c44da888da325067f9ece3), DecoratedKey(40d6f31d-4b37-492e-b06c-9de0088de83f, 40d6f31d4b37492eb06c9de0088de83f)), Interval(DecoratedKey(a5f8d3d8-d26a-47fd-904c-8d55784776fc, a5f8d3d8d26a47fd904c8d55784776fc), DecoratedKey(762f9402-e5f6-44bb-824c-f93170c2f508, 762f9402e5f644bb824cf93170c2f508)), Interval(DecoratedKey(a27d2f3b-8255-42fb-a8d5-5f0fe488dadb, a27d2f3b825542fba8d55f0fe488dadb), DecoratedKey(7582809c-34b3-4736-8dfe-19811303bbfa, 7582809c34b347368dfe19811303bbfa)), Interval(DecoratedKey(d72c5963-ebe8-4e13-a74b-5584ca1d053c, d72c5963ebe84e13a74b5584ca1d053c), DecoratedKey(4962307f-261d-469a-b48b-1de7cd7a7700, 4962307f261d469ab48b1de7cd7a7700)), This shouldn't ever happen, so I'll do some poking around to see where these come from.
        Hide
        paul cannon added a comment -

        These values come right from the SSTables. I've been looking through code to see if I can find any possibility of bad values being written to an SSTable, but there might be a simpler explanation:

        Is there any possibility that you have configured a different partitioner for Cassandra 1.0.8 from the one you used when writing the SSTables (0.8.10, I suppose)?

        Show
        paul cannon added a comment - These values come right from the SSTables. I've been looking through code to see if I can find any possibility of bad values being written to an SSTable, but there might be a simpler explanation: Is there any possibility that you have configured a different partitioner for Cassandra 1.0.8 from the one you used when writing the SSTables (0.8.10, I suppose)?
        Hide
        Wenjun added a comment -

        I just attached yaml files for both 0.8.10 and 1.0.8 (from your branch).

        Show
        Wenjun added a comment - I just attached yaml files for both 0.8.10 and 1.0.8 (from your branch).
        Hide
        paul cannon added a comment -

        Ok, looks like both are RandomPartitioner. I'll keep investigating.

        Show
        paul cannon added a comment - Ok, looks like both are RandomPartitioner. I'll keep investigating.
        Hide
        Wenjun added a comment -

        Paul,

        so you know: I just tried 1.1.0-beta2 and seeing the same error.

        Show
        Wenjun added a comment - Paul, so you know: I just tried 1.1.0-beta2 and seeing the same error.
        Hide
        paul cannon added a comment -

        Yeah, the problem is almost certainly either (a) some important difference in the way it's being used now versus the way it was used before, or (b) some sort of bug in 0.8.10. I don't think 1.0.8 or 1.1.0 are acting improperly given the data and configuration here; I'm just hoping I can help you sort out whatever datatype expectation mismatch or invalid sstables you have.

        Show
        paul cannon added a comment - Yeah, the problem is almost certainly either (a) some important difference in the way it's being used now versus the way it was used before, or (b) some sort of bug in 0.8.10. I don't think 1.0.8 or 1.1.0 are acting improperly given the data and configuration here; I'm just hoping I can help you sort out whatever datatype expectation mismatch or invalid sstables you have.
        Hide
        paul cannon added a comment -

        Wenjun, are you able to tell from the UUID keys shown which ColumnFamily is having these troubles? I can't quite tell for sure from the logs. If necessary, we can add more asserts to identify the right place, but we can skip that step if you already know which one it is.

        Show
        paul cannon added a comment - Wenjun, are you able to tell from the UUID keys shown which ColumnFamily is having these troubles? I can't quite tell for sure from the logs. If necessary, we can add more asserts to identify the right place, but we can skip that step if you already know which one it is.
        Hide
        Wenjun added a comment -

        Paul, yes, finally I am able to narrow it down to this one CF. I truncated data from all other CFs, ran 'cleanp' and 'scrub', and it is still happening. What else can I do to help debugging this issue? The followings are definition of this CF:

        ColumnFamily: UserAgreementStatus
        Key Validation Class: org.apache.cassandra.db.marshal.BytesType
        Default column value validator: org.apache.cassandra.db.marshal.BytesType
        Columns sorted by: org.apache.cassandra.db.marshal.UTF8Type
        Row cache size / save period in seconds: 0.0/0
        Row Cache Provider: org.apache.cassandra.cache.ConcurrentLinkedHashCacheProvider
        Key cache size / save period in seconds: 200000.0/14400
        Memtable thresholds: 0.45468749999999997/1440/97 (millions of ops/minutes/MB)
        GC grace seconds: 864000
        Compaction min/max thresholds: 4/32
        Read repair chance: 1.0
        Replicate on write: false
        Built indexes: [UserAgreementStatus.userId]
        Column Metadata:
        Column Name: agreementName
        Validation Class: org.apache.cassandra.db.marshal.UTF8Type
        Column Name: response
        Validation Class: org.apache.cassandra.db.marshal.UTF8Type
        Column Name: userId
        Validation Class: org.apache.cassandra.db.marshal.LexicalUUIDType
        Index Name: userId
        Index Type: KEYS
        Column Name: viewTime
        Validation Class: org.apache.cassandra.db.marshal.LongType

        Log right before the exception:
        DEBUG [SSTableBatchOpen:2] 2012-03-30 12:09:20,277 SSTableReader.java (line 190) INDEX LOAD TIME for /home/cassandra/var/lib/cassandra/d
        ata/Appoji/UserAgreementStatus.userId-f-56: 3 ms.
        DEBUG [SSTableBatchOpen:2] 2012-03-30 12:09:20,277 SSTableReader.java (line 193) key cache contains 0/0 keys

        Show
        Wenjun added a comment - Paul, yes, finally I am able to narrow it down to this one CF. I truncated data from all other CFs, ran 'cleanp' and 'scrub', and it is still happening. What else can I do to help debugging this issue? The followings are definition of this CF: ColumnFamily: UserAgreementStatus Key Validation Class: org.apache.cassandra.db.marshal.BytesType Default column value validator: org.apache.cassandra.db.marshal.BytesType Columns sorted by: org.apache.cassandra.db.marshal.UTF8Type Row cache size / save period in seconds: 0.0/0 Row Cache Provider: org.apache.cassandra.cache.ConcurrentLinkedHashCacheProvider Key cache size / save period in seconds: 200000.0/14400 Memtable thresholds: 0.45468749999999997/1440/97 (millions of ops/minutes/MB) GC grace seconds: 864000 Compaction min/max thresholds: 4/32 Read repair chance: 1.0 Replicate on write: false Built indexes: [UserAgreementStatus.userId] Column Metadata: Column Name: agreementName Validation Class: org.apache.cassandra.db.marshal.UTF8Type Column Name: response Validation Class: org.apache.cassandra.db.marshal.UTF8Type Column Name: userId Validation Class: org.apache.cassandra.db.marshal.LexicalUUIDType Index Name: userId Index Type: KEYS Column Name: viewTime Validation Class: org.apache.cassandra.db.marshal.LongType Log right before the exception: DEBUG [SSTableBatchOpen:2] 2012-03-30 12:09:20,277 SSTableReader.java (line 190) INDEX LOAD TIME for /home/cassandra/var/lib/cassandra/d ata/Appoji/UserAgreementStatus.userId-f-56: 3 ms. DEBUG [SSTableBatchOpen:2] 2012-03-30 12:09:20,277 SSTableReader.java (line 193) key cache contains 0/0 keys
        Hide
        paul cannon added a comment -

        Wenjun- it would help at this point to be sure whether or not your sstables really do have keys which are out of order. Could you run the sstablekeys tool on the data file for that UserAgreementStatus CF? It looks like it is at /home/cassandra/var/lib/cassandra/data/Appoji/UserAgreementStatus/Appoji-UserAgreementStatus.userId-g-*-Data.db. We want to check that the byte sequences are in order:

        $ for s in /home/cassandra/var/lib/cassandra/data/Appoji/UserAgreementStatus/Appoji-UserAgreementStatus.userId-g-*-{Data,Index}.db; do
        >     echo "checking $s"
        >     bin/sstablekeys "$s" | sort -c
        > done
        

        If that doesn't give any output, then maybe there really is a bug in the 1.0/1.1 code that we need to look at.

        Show
        paul cannon added a comment - Wenjun- it would help at this point to be sure whether or not your sstables really do have keys which are out of order. Could you run the sstablekeys tool on the data file for that UserAgreementStatus CF? It looks like it is at /home/cassandra/var/lib/cassandra/data/Appoji/UserAgreementStatus/Appoji-UserAgreementStatus.userId-g-*-Data.db . We want to check that the byte sequences are in order: $ for s in /home/cassandra/var/lib/cassandra/data/Appoji/UserAgreementStatus/Appoji-UserAgreementStatus.userId-g-*-{Data,Index}.db; do > echo "checking $s" > bin/sstablekeys "$s" | sort -c > done If that doesn't give any output, then maybe there really is a bug in the 1.0/1.1 code that we need to look at.
        Hide
        Wenjun added a comment -

        Paul, attache is results from sstablekeys

        Thanks

        Show
        Wenjun added a comment - Paul, attache is results from sstablekeys Thanks
        Hide
        paul cannon added a comment -

        Ok, so there are definitely out-of-order keys in your sstables. I have no good theories as to how that happened- I don't think anyone else has run into this. Were you possibly using any sort of custom types or parameterized types with 0.8.9? Custom anything?

        Either way, the thing to be done now is probably to get your data sorted. Maybe we can come up with a one-off tool of some kind to read the values and write them back out in a sorted way.

        Show
        paul cannon added a comment - Ok, so there are definitely out-of-order keys in your sstables. I have no good theories as to how that happened- I don't think anyone else has run into this. Were you possibly using any sort of custom types or parameterized types with 0.8.9? Custom anything? Either way, the thing to be done now is probably to get your data sorted. Maybe we can come up with a one-off tool of some kind to read the values and write them back out in a sorted way.
        Hide
        Yuki Morishita added a comment -

        I don't have a clue about the cause, but since corrupted files are index column families, I think work around is to remove all those corrupted index sstables, upgrade C*, then rebuild index using 'nodetool rebuild_index'.

        Show
        Yuki Morishita added a comment - I don't have a clue about the cause, but since corrupted files are index column families, I think work around is to remove all those corrupted index sstables, upgrade C*, then rebuild index using 'nodetool rebuild_index'.
        Hide
        paul cannon added a comment -

        Yuki- there is an index sstable with out-of-order keys, and that one could be fixed as you suggest, but the actual data sstable also has out-of-order keys.

        Show
        paul cannon added a comment - Yuki- there is an index sstable with out-of-order keys, and that one could be fixed as you suggest, but the actual data sstable also has out-of-order keys.
        Hide
        Wenjun added a comment -

        I am able to fix the issue by doing the followings:

        1. ran original command for creating the CF (replacing create with update) in cassandra-cli, got an error "cannot modify index name". (I looked it up in Cassandra mailing list and did not found any reference, so not sure what it means).

        2. ran the command again WITHOUT index in column_metadata.

        3. ran the command WITH index in column_metadata.

        Now I am able to start 1.0.8 and 1.1.0-beta2. I double-checked that CF and it seems all the data and index are fine. So, let me know if I need to check anything else.

        Thanks

        Show
        Wenjun added a comment - I am able to fix the issue by doing the followings: 1. ran original command for creating the CF (replacing create with update) in cassandra-cli, got an error "cannot modify index name". (I looked it up in Cassandra mailing list and did not found any reference, so not sure what it means). 2. ran the command again WITHOUT index in column_metadata. 3. ran the command WITH index in column_metadata. Now I am able to start 1.0.8 and 1.1.0-beta2. I double-checked that CF and it seems all the data and index are fine. So, let me know if I need to check anything else. Thanks
        Hide
        paul cannon added a comment -

        Oh, good. I'm glad that was doable.

        Before we close the ticket, is there anything at all from your experience or Cassandra usage that may have been unusual- hardware, platform, storage method, custom data or index types, etc? I would really like at least to get some clues about how this happened, if possible.

        Show
        paul cannon added a comment - Oh, good. I'm glad that was doable. Before we close the ticket, is there anything at all from your experience or Cassandra usage that may have been unusual- hardware, platform, storage method, custom data or index types, etc? I would really like at least to get some clues about how this happened, if possible.
        Hide
        Wenjun added a comment -

        I found something over the weekend: it seems 0.8.10 does not allow duplicate index names for different CFs. We do have CFs having same name (such as userId) for their indexes, which means some earlier version must have allowed it (we started from 0.7.4). Can this be the cause?

        Show
        Wenjun added a comment - I found something over the weekend: it seems 0.8.10 does not allow duplicate index names for different CFs. We do have CFs having same name (such as userId) for their indexes, which means some earlier version must have allowed it (we started from 0.7.4). Can this be the cause?
        Hide
        Wenjun added a comment -

        I found something over the weekend: it seems 0.8.10 does not allow duplicate index names for different CFs. We do have CFs having same name (such as userId) for their indexes, which means some earlier version must have allowed it (we started from 0.7.4). Can this be the cause?

        Show
        Wenjun added a comment - I found something over the weekend: it seems 0.8.10 does not allow duplicate index names for different CFs. We do have CFs having same name (such as userId) for their indexes, which means some earlier version must have allowed it (we started from 0.7.4). Can this be the cause?
        Hide
        paul cannon added a comment -

        Ok. We'll keep that info around in case we ever see something like this again. Thanks.

        I do recommend that these asserts (patch attached, also at my pending/4078-2 tag in github) get committed to mainline Cassandra, though, to help protect against this sort of situation. The asserts in this patch will not catch all possible updates to SSTable.last, but they surround some of the more important (and less frequent) places.

        Also, the asserts inside the IntervalTree creation should avoid getting into confusing StackOverflowError situations.

        Show
        paul cannon added a comment - Ok. We'll keep that info around in case we ever see something like this again. Thanks. I do recommend that these asserts (patch attached, also at my pending/4078-2 tag in github) get committed to mainline Cassandra, though, to help protect against this sort of situation. The asserts in this patch will not catch all possible updates to SSTable.last, but they surround some of the more important (and less frequent) places. Also, the asserts inside the IntervalTree creation should avoid getting into confusing StackOverflowError situations.
        Hide
        Jonathan Ellis added a comment -

        alternate patch attached that converts the ordering check in SSTW.beforeAppend to an assert

        Show
        Jonathan Ellis added a comment - alternate patch attached that converts the ordering check in SSTW.beforeAppend to an assert
        Hide
        paul cannon added a comment -
        assert decoratedKey == null : "Keys must not be null";
        

        (-1)

        Show
        paul cannon added a comment - assert decoratedKey == null : "Keys must not be null"; (-1)
        Hide
        Jonathan Ellis added a comment -

        committed w/ that fixed

        Show
        Jonathan Ellis added a comment - committed w/ that fixed

          People

          • Assignee:
            paul cannon
            Reporter:
            Wenjun
            Reviewer:
            Jonathan Ellis
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development