Details

    • Type: Bug
    • Status: Resolved
    • Priority: Blocker
    • Resolution: Fixed
    • Fix Version/s: 1.2.4
    • Component/s: None
    • Labels:
      None
    • Environment:

      Description

      I get SSL and snappy compression errors in multiple datacenter setup.

      The setup is simple: 3 nodes in AWS east, 3 nodes in Rackspace. I use slightly modified Ec2MultiRegionSnitch in Rackspace (I just added a regex able to parse the Rackspace/Openstack availability zone which happens to be in unusual format).

      During nodetool rebuild tests I managed to (consistently) trigger the following error:

      2013-03-19 12:42:16.059+0100 [Thread-13] [DEBUG] IncomingTcpConnection.java(79) org.apache.cassandra.net.IncomingTcpConnection: IOException reading from socket; closing
      java.io.IOException: FAILED_TO_UNCOMPRESS(5)
      	at org.xerial.snappy.SnappyNative.throw_error(SnappyNative.java:78)
      	at org.xerial.snappy.SnappyNative.rawUncompress(Native Method)
      	at org.xerial.snappy.Snappy.rawUncompress(Snappy.java:391)
      	at org.apache.cassandra.io.compress.SnappyCompressor.uncompress(SnappyCompressor.java:93)
      	at org.apache.cassandra.streaming.compress.CompressedInputStream.decompress(CompressedInputStream.java:101)
      	at org.apache.cassandra.streaming.compress.CompressedInputStream.read(CompressedInputStream.java:79)
      	at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:337)
      	at org.apache.cassandra.utils.BytesReadTracker.readUnsignedShort(BytesReadTracker.java:140)
      	at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.java:361)
      	at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil.java:371)
      	at org.apache.cassandra.streaming.IncomingStreamReader.streamIn(IncomingStreamReader.java:160)
      	at org.apache.cassandra.streaming.IncomingStreamReader.read(IncomingStreamReader.java:122)
      	at org.apache.cassandra.net.IncomingTcpConnection.stream(IncomingTcpConnection.java:226)
      	at org.apache.cassandra.net.IncomingTcpConnection.handleStream(IncomingTcpConnection.java:166)
      	at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:66)
      

      The exception is raised during DB file download. What is strange is the following:

      • the exception is raised only when rebuildig from AWS into Rackspace
      • the exception is raised only when all nodes are up and running in AWS (all 3). In other words, if I bootstrap from one or two nodes in AWS, the command succeeds.

      Packet-level inspection revealed malformed packets on both ends of communication (the packet is considered malformed on the machine it originates on).

      Further investigation raised two more concerns:

      • We managed to get another stacktrace when testing the scenario. The exception was raised only once during the tests and was raised when I throttled the inter-datacenter bandwidth to 1Mbps.
      java.lang.RuntimeException: javax.net.ssl.SSLException: bad record MAC
      	at com.google.common.base.Throwables.propagate(Throwables.java:160)
      	at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:32)
      	at java.lang.Thread.run(Thread.java:662)
      Caused by: javax.net.ssl.SSLException: bad record MAC
      	at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190)
      	at com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1649)
      	at com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1607)
      	at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:859)
      	at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:755)
      	at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
      	at org.apache.cassandra.streaming.compress.CompressedInputStream$Reader.runMayThrow(CompressedInputStream.java:151)
      	at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28)
      	... 1 more
      

      This is pure SSL error with no snappy interference.

      • I managed to trigger the exception during nodetool repair tests when replacing dead node with a new one on the aws side, which means the problem is not restricted to the one-way scenario only.
      2013-03-27 14:06:03.033+0100 [Thread-137] [INFO] StreamInSession.java(136) org.apache.cassandra.streaming.StreamInSession: Streaming of file /path/to/cassandra/data/ks/cf/ks-cf-ib-2-Data.db sections=3 progress=0/20513 - 0% for org.apache.cassandra.streaming.StreamInSession@14450ae7 failed: requesting a retry.
      2013-03-27 14:06:03.033+0100 [Thread-138] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-98-Data.db
      2013-03-27 14:06:03.033+0100 [Thread-138] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-98-Filter.db
      2013-03-27 14:06:03.034+0100 [Thread-138] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-98-TOC.txt
      2013-03-27 14:06:03.034+0100 [Thread-137] [DEBUG] IncomingTcpConnection.java(91) org.apache.cassandra.net.IncomingTcpConnection: IOException reading from socket; closing
      java.io.IOException: FAILED_TO_UNCOMPRESS(5)
      	at org.xerial.snappy.SnappyNative.throw_error(SnappyNative.java:78)
      	at org.xerial.snappy.SnappyNative.rawUncompress(Native Method)
      	at org.xerial.snappy.Snappy.rawUncompress(Snappy.java:391)
      	at org.apache.cassandra.io.compress.SnappyCompressor.uncompress(SnappyCompressor.java:93)
      	at org.apache.cassandra.streaming.compress.CompressedInputStream.decompress(CompressedInputStream.java:101)
      	at org.apache.cassandra.streaming.compress.CompressedInputStream.read(CompressedInputStream.java:79)
      	at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:320)
      	at org.apache.cassandra.utils.BytesReadTracker.readUnsignedShort(BytesReadTracker.java:140)
      	at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.java:361)
      	at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil.java:371)
      	at org.apache.cassandra.streaming.IncomingStreamReader.streamIn(IncomingStreamReader.java:160)
      	at org.apache.cassandra.streaming.IncomingStreamReader.read(IncomingStreamReader.java:122)
      	at org.apache.cassandra.net.IncomingTcpConnection.stream(IncomingTcpConnection.java:238)
      	at org.apache.cassandra.net.IncomingTcpConnection.handleStream(IncomingTcpConnection.java:178)
      	at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:78)
      
      1. 5391-1.2.3.txt
        1 kB
        Yuki Morishita
      2. 5391-1.2.txt
        1 kB
        Yuki Morishita
      3. 5391-v2-1.2.txt
        1 kB
        Yuki Morishita

        Issue Links

          Activity

          Hide
          ondrej.cernos Ondřej Černoš added a comment -

          With SSL switched off all the scenarios work well.

          Show
          ondrej.cernos Ondřej Černoš added a comment - With SSL switched off all the scenarios work well.
          Hide
          ondrej.cernos Ondřej Černoš added a comment -

          After clarifying CASSANDRA-5390 I tried to switch to DeflateCompressor SSTable compression algorithm. The problem is compression-algorithm independent:

          2013-03-27 16:19:57.633+0100 [Thread-31] [INFO] StreamInSession.java(136) org.apache.cassandra.streaming.StreamInSession: component=c4 Streaming of file /mnt/ebs/cassandra/data/c4/user_profile_settings/c4-user_profile_settings-ib-2-Data.db sections=130 progress=0/1628502 - 0% for org.apache.cassandra.streaming.StreamInSession@20f92649 failed: requesting a retry.
          2013-03-27 16:19:57.633+0100 [Thread-31] [DEBUG] IncomingTcpConnection.java(91) org.apache.cassandra.net.IncomingTcpConnection: component=c4 IOException reading from socket; closing
          java.io.IOException: CRC unmatched
          	at org.apache.cassandra.streaming.compress.CompressedInputStream.decompress(CompressedInputStream.java:111)
          	at org.apache.cassandra.streaming.compress.CompressedInputStream.read(CompressedInputStream.java:79)
          	at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:320)
          	at org.apache.cassandra.utils.BytesReadTracker.readUnsignedShort(BytesReadTracker.java:140)
          	at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.java:361)
          	at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil.java:371)
          	at org.apache.cassandra.streaming.IncomingStreamReader.streamIn(IncomingStreamReader.java:160)
          	at org.apache.cassandra.streaming.IncomingStreamReader.read(IncomingStreamReader.java:122)
          	at org.apache.cassandra.net.IncomingTcpConnection.stream(IncomingTcpConnection.java:238)
          	at org.apache.cassandra.net.IncomingTcpConnection.handleStream(IncomingTcpConnection.java:178)
          	at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:78)
          
          Show
          ondrej.cernos Ondřej Černoš added a comment - After clarifying CASSANDRA-5390 I tried to switch to DeflateCompressor SSTable compression algorithm. The problem is compression-algorithm independent: 2013-03-27 16:19:57.633+0100 [Thread-31] [INFO] StreamInSession.java(136) org.apache.cassandra.streaming.StreamInSession: component=c4 Streaming of file /mnt/ebs/cassandra/data/c4/user_profile_settings/c4-user_profile_settings-ib-2-Data.db sections=130 progress=0/1628502 - 0% for org.apache.cassandra.streaming.StreamInSession@20f92649 failed: requesting a retry. 2013-03-27 16:19:57.633+0100 [Thread-31] [DEBUG] IncomingTcpConnection.java(91) org.apache.cassandra.net.IncomingTcpConnection: component=c4 IOException reading from socket; closing java.io.IOException: CRC unmatched at org.apache.cassandra.streaming.compress.CompressedInputStream.decompress(CompressedInputStream.java:111) at org.apache.cassandra.streaming.compress.CompressedInputStream.read(CompressedInputStream.java:79) at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:320) at org.apache.cassandra.utils.BytesReadTracker.readUnsignedShort(BytesReadTracker.java:140) at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.java:361) at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil.java:371) at org.apache.cassandra.streaming.IncomingStreamReader.streamIn(IncomingStreamReader.java:160) at org.apache.cassandra.streaming.IncomingStreamReader.read(IncomingStreamReader.java:122) at org.apache.cassandra.net.IncomingTcpConnection.stream(IncomingTcpConnection.java:238) at org.apache.cassandra.net.IncomingTcpConnection.handleStream(IncomingTcpConnection.java:178) at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:78)
          Hide
          ondrej.cernos Ondřej Černoš added a comment -

          Update:

          With SSTable compression switched off the bug disappears. When I run nodetool rebuild us-east on a Rackspace node, it fetches the data correctly and when I compare the md5 of the DB file on an AWS node (after flush and compaction), it is exactly the same as on the Rackspace node.
          It means the problem is only with compressed SSTables, but the problem is independent on chosen compression algorithm. And only with SSL switched on for inter-DC communication.

          Show
          ondrej.cernos Ondřej Černoš added a comment - Update: With SSTable compression switched off the bug disappears. When I run nodetool rebuild us-east on a Rackspace node, it fetches the data correctly and when I compare the md5 of the DB file on an AWS node (after flush and compaction), it is exactly the same as on the Rackspace node. It means the problem is only with compressed SSTables, but the problem is independent on chosen compression algorithm. And only with SSL switched on for inter-DC communication.
          Hide
          jbellis Jonathan Ellis added a comment -

          Can you shed any light, Jake?

          Show
          jbellis Jonathan Ellis added a comment - Can you shed any light, Jake?
          Hide
          tjake T Jake Luciani added a comment -

          Nope, we don't use SSL. Does it work when you disable internode compression?

          Show
          tjake T Jake Luciani added a comment - Nope, we don't use SSL. Does it work when you disable internode compression?
          Hide
          ondrej.cernos Ondřej Černoš added a comment -

          Internode compression settings didn't have any influence on the problem. The case is very strange:

          • it happens only when SSTables are compressed (see the update above)
          • it is independent on SSTable compression implementation however (also see above)
          • it happens only when "enough" (all 3) nodes are switched on in AWS. With 2 or 1 only the problem disappears

          Do you have a recommendation on what to investigate further? I already asked the network team to check networking - they say all is ok - and our operations, who also cannot identify anything, except for the fact MTU is different in Rackspace and AWS, so packet from AWS to Rackspace get fragmented.

          Show
          ondrej.cernos Ondřej Černoš added a comment - Internode compression settings didn't have any influence on the problem. The case is very strange: it happens only when SSTables are compressed (see the update above) it is independent on SSTable compression implementation however (also see above) it happens only when "enough" (all 3) nodes are switched on in AWS. With 2 or 1 only the problem disappears Do you have a recommendation on what to investigate further? I already asked the network team to check networking - they say all is ok - and our operations, who also cannot identify anything, except for the fact MTU is different in Rackspace and AWS, so packet from AWS to Rackspace get fragmented.
          Hide
          ondrej.cernos Ondřej Černoš added a comment -

          I am becoming quite sure the problem is a race condition in Cassandra code handling decompression of sstables when these are streamed from the remote datacenter.

          Both traces - when snappy is used and when the java zip is used - share the same calls, see above.

          I switched trace level in log4j and this is what I found:

          • when 2 and more nodes live in the remote DC, cassandra fires two threads downloading the same file
          • when only 1 node lives in the remote DC, only one thread downloads the file

          This is how it looks in log:

          2013-03-28 13:44:57.301+0100 [Thread-22] [DEBUG] StreamInSession.java(104) org.apache.cassandra.streaming.StreamInSession: Adding file /path/to/cassandra/data/ks/cf/ks-cf-ib-2-Data.db to Stream Request queue
          2013-03-28 13:44:57.301+0100 [Thread-22] [DEBUG] StreamInSession.java(104) org.apache.cassandra.streaming.StreamInSession: Adding file /path/to/cassandra/data/ks/cf/ks-cf-ib-1-Data.db to Stream Request queue
          2013-03-28 13:44:57.338+0100 [Thread-23] [DEBUG] StreamInSession.java(104) org.apache.cassandra.streaming.StreamInSession: Adding file /path/to/cassandra/data/ks/cf/ks-cf-ib-2-Data.db to Stream Request queue
          2013-03-28 13:44:57.340+0100 [Thread-23] [DEBUG] StreamInSession.java(104) org.apache.cassandra.streaming.StreamInSession: Adding file /path/to/cassandra/data/ks/cf/ks-cf-ib-1-Data.db to Stream Request queue
          

          And here is the result grepped on the two threads:

          2013-03-28 13:44:57.477+0100 [Thread-22] [TRACE] SSTableWriter.java(145) org.apache.cassandra.io.sstable.SSTableWriter: wrote DecoratedKey(-8516046549581000893, 6663363133663230623932663663303732623735653332643964616261623165) at 183591
          2013-03-28 13:44:57.477+0100 [Thread-22] [TRACE] SSTableWriter.java(463) org.apache.cassandra.io.sstable.SSTableWriter: wrote index entry: org.apache.cassandra.db.RowIndexEntry@7b553d18 at 16192
          2013-03-28 13:44:57.477+0100 [Thread-22] [TRACE] SSTableWriter.java(145) org.apache.cassandra.io.sstable.SSTableWriter: wrote DecoratedKey(-8513551951874950453, 3934363831326161323235653165613662613039346233356264386461653735) at 183995
          2013-03-28 13:44:57.478+0100 [Thread-22] [TRACE] SSTableWriter.java(463) org.apache.cassandra.io.sstable.SSTableWriter: wrote index entry: org.apache.cassandra.db.RowIndexEntry@d5f0688 at 16238
          2013-03-28 13:44:57.501+0100 [Thread-22] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-1-Data.db
          2013-03-28 13:44:57.501+0100 [Thread-22] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-1-Filter.db
          2013-03-28 13:44:57.501+0100 [Thread-22] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-1-TOC.txt
          2013-03-28 13:44:57.501+0100 [Thread-22] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-1-CompressionInfo.db
          2013-03-28 13:44:57.502+0100 [Thread-22] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-1-Index.db
          2013-03-28 13:44:57.502+0100 [Thread-22] [DEBUG] SSTable.java(154) org.apache.cassandra.io.sstable.SSTable: Deleted /path/to/cassandra/data/ks/cf/ks-cf-tmp-ib-1
          2013-03-28 13:44:57.503+0100 [Thread-22] [INFO] StreamInSession.java(136) org.apache.cassandra.streaming.StreamInSession: Streaming of file /path/to/cassandra/data/ks/cf/ks-cf-ib-2-Data.db sections=130 progress=67628/1583497 - 4% for org.apache.cassandra.streaming.StreamInSession@21400eb0 failed: requesting a retry.
          2013-03-28 13:44:57.504+0100 [Thread-22] [DEBUG] IncomingTcpConnection.java(91) org.apache.cassandra.net.IncomingTcpConnection: IOException reading from socket; closing
          java.io.IOException: CRC unmatched
                  at org.apache.cassandra.streaming.compress.CompressedInputStream.decompress(CompressedInputStream.java:111)
                  at org.apache.cassandra.streaming.compress.CompressedInputStream.read(CompressedInputStream.java:79)
                  at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:320)
                  at org.apache.cassandra.utils.BytesReadTracker.readUnsignedShort(BytesReadTracker.java:140)
                  at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.java:361)
                  at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil.java:371)
                  at org.apache.cassandra.streaming.IncomingStreamReader.streamIn(IncomingStreamReader.java:160)
                  at org.apache.cassandra.streaming.IncomingStreamReader.read(IncomingStreamReader.java:122)
                  at org.apache.cassandra.net.IncomingTcpConnection.stream(IncomingTcpConnection.java:238)
                  at org.apache.cassandra.net.IncomingTcpConnection.handleStream(IncomingTcpConnection.java:178)
                  at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:78)
          
          2013-03-28 13:44:58.070+0100 [Thread-23] [TRACE] SSTableWriter.java(463) org.apache.cassandra.io.sstable.SSTableWriter: wrote index entry: org.apache.cassandra.db.RowIndexEntry@db766c1 at 106582
          2013-03-28 13:44:58.071+0100 [Thread-23] [TRACE] SSTableWriter.java(145) org.apache.cassandra.io.sstable.SSTableWriter: wrote DecoratedKey(-4829320003365722996, 6333383266393230353964313666633136356335333437353637373735653065) at 1217942
          2013-03-28 13:44:58.071+0100 [Thread-23] [TRACE] SSTableWriter.java(463) org.apache.cassandra.io.sstable.SSTableWriter: wrote index entry: org.apache.cassandra.db.RowIndexEntry@3bb0ff0 at 106628
          2013-03-28 13:44:58.071+0100 [Thread-23] [TRACE] SSTableWriter.java(145) org.apache.cassandra.io.sstable.SSTableWriter: wrote DecoratedKey(-4827623571007838156, 6162376162333238393739643930336266616566393039376131366238386166) at 1218191
          2013-03-28 13:44:58.071+0100 [Thread-23] [TRACE] SSTableWriter.java(463) org.apache.cassandra.io.sstable.SSTableWriter: wrote index entry: org.apache.cassandra.db.RowIndexEntry@6e135779 at 106674
          2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-2-Data.db
          2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-2-Filter.db
          2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-2-TOC.txt
          2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-2-CompressionInfo.db
          2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-2-Index.db
          2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] SSTable.java(154) org.apache.cassandra.io.sstable.SSTable: Deleted /path/to/cassandra/data/ks/cf/ks-cf-tmp-ib-2
          2013-03-28 13:44:58.091+0100 [Thread-23] [INFO] StreamInSession.java(136) org.apache.cassandra.streaming.StreamInSession: Streaming of file /path/to/cassandra/data/ks/cf/ks-cf-ib-2-Data.db sections=131 progress=406399/1638227 - 24% for org.apache.cassandra.streaming.StreamInSession@37d40164 failed: requesting a retry.
          2013-03-28 13:44:58.092+0100 [Thread-23] [DEBUG] IncomingTcpConnection.java(91) org.apache.cassandra.net.IncomingTcpConnection: IOException reading from socket; closing
          java.io.IOException: CRC unmatched
                  at org.apache.cassandra.streaming.compress.CompressedInputStream.decompress(CompressedInputStream.java:111)
                  at org.apache.cassandra.streaming.compress.CompressedInputStream.read(CompressedInputStream.java:79)
                  at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:320)
                  at org.apache.cassandra.utils.BytesReadTracker.readUnsignedShort(BytesReadTracker.java:140)
                  at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.java:361)
                  at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil.java:371)
                  at org.apache.cassandra.streaming.IncomingStreamReader.streamIn(IncomingStreamReader.java:160)
                  at org.apache.cassandra.streaming.IncomingStreamReader.read(IncomingStreamReader.java:122)
                  at org.apache.cassandra.net.IncomingTcpConnection.stream(IncomingTcpConnection.java:238)
                  at org.apache.cassandra.net.IncomingTcpConnection.handleStream(IncomingTcpConnection.java:178)
                  at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:78)
          

          This is common for snappy and java zip:

          	at org.apache.cassandra.streaming.compress.CompressedInputStream.read(CompressedInputStream.java:79)
          	at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:320)
          	at org.apache.cassandra.utils.BytesReadTracker.readUnsignedShort(BytesReadTracker.java:140)
          	at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.java:361)
          	at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil.java:371)
          	at org.apache.cassandra.streaming.IncomingStreamReader.streamIn(IncomingStreamReader.java:160)
          	at org.apache.cassandra.streaming.IncomingStreamReader.read(IncomingStreamReader.java:122)
          	at org.apache.cassandra.net.IncomingTcpConnection.stream(IncomingTcpConnection.java:238)
          	at org.apache.cassandra.net.IncomingTcpConnection.handleStream(IncomingTcpConnection.java:178)
          	at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:78)
          

          When the download runs in single thread, the problem disappears.

          Show
          ondrej.cernos Ondřej Černoš added a comment - I am becoming quite sure the problem is a race condition in Cassandra code handling decompression of sstables when these are streamed from the remote datacenter. Both traces - when snappy is used and when the java zip is used - share the same calls, see above. I switched trace level in log4j and this is what I found: when 2 and more nodes live in the remote DC, cassandra fires two threads downloading the same file when only 1 node lives in the remote DC, only one thread downloads the file This is how it looks in log: 2013-03-28 13:44:57.301+0100 [Thread-22] [DEBUG] StreamInSession.java(104) org.apache.cassandra.streaming.StreamInSession: Adding file /path/to/cassandra/data/ks/cf/ks-cf-ib-2-Data.db to Stream Request queue 2013-03-28 13:44:57.301+0100 [Thread-22] [DEBUG] StreamInSession.java(104) org.apache.cassandra.streaming.StreamInSession: Adding file /path/to/cassandra/data/ks/cf/ks-cf-ib-1-Data.db to Stream Request queue 2013-03-28 13:44:57.338+0100 [Thread-23] [DEBUG] StreamInSession.java(104) org.apache.cassandra.streaming.StreamInSession: Adding file /path/to/cassandra/data/ks/cf/ks-cf-ib-2-Data.db to Stream Request queue 2013-03-28 13:44:57.340+0100 [Thread-23] [DEBUG] StreamInSession.java(104) org.apache.cassandra.streaming.StreamInSession: Adding file /path/to/cassandra/data/ks/cf/ks-cf-ib-1-Data.db to Stream Request queue And here is the result grepped on the two threads: 2013-03-28 13:44:57.477+0100 [Thread-22] [TRACE] SSTableWriter.java(145) org.apache.cassandra.io.sstable.SSTableWriter: wrote DecoratedKey(-8516046549581000893, 6663363133663230623932663663303732623735653332643964616261623165) at 183591 2013-03-28 13:44:57.477+0100 [Thread-22] [TRACE] SSTableWriter.java(463) org.apache.cassandra.io.sstable.SSTableWriter: wrote index entry: org.apache.cassandra.db.RowIndexEntry@7b553d18 at 16192 2013-03-28 13:44:57.477+0100 [Thread-22] [TRACE] SSTableWriter.java(145) org.apache.cassandra.io.sstable.SSTableWriter: wrote DecoratedKey(-8513551951874950453, 3934363831326161323235653165613662613039346233356264386461653735) at 183995 2013-03-28 13:44:57.478+0100 [Thread-22] [TRACE] SSTableWriter.java(463) org.apache.cassandra.io.sstable.SSTableWriter: wrote index entry: org.apache.cassandra.db.RowIndexEntry@d5f0688 at 16238 2013-03-28 13:44:57.501+0100 [Thread-22] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-1-Data.db 2013-03-28 13:44:57.501+0100 [Thread-22] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-1-Filter.db 2013-03-28 13:44:57.501+0100 [Thread-22] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-1-TOC.txt 2013-03-28 13:44:57.501+0100 [Thread-22] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-1-CompressionInfo.db 2013-03-28 13:44:57.502+0100 [Thread-22] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-1-Index.db 2013-03-28 13:44:57.502+0100 [Thread-22] [DEBUG] SSTable.java(154) org.apache.cassandra.io.sstable.SSTable: Deleted /path/to/cassandra/data/ks/cf/ks-cf-tmp-ib-1 2013-03-28 13:44:57.503+0100 [Thread-22] [INFO] StreamInSession.java(136) org.apache.cassandra.streaming.StreamInSession: Streaming of file /path/to/cassandra/data/ks/cf/ks-cf-ib-2-Data.db sections=130 progress=67628/1583497 - 4% for org.apache.cassandra.streaming.StreamInSession@21400eb0 failed: requesting a retry. 2013-03-28 13:44:57.504+0100 [Thread-22] [DEBUG] IncomingTcpConnection.java(91) org.apache.cassandra.net.IncomingTcpConnection: IOException reading from socket; closing java.io.IOException: CRC unmatched at org.apache.cassandra.streaming.compress.CompressedInputStream.decompress(CompressedInputStream.java:111) at org.apache.cassandra.streaming.compress.CompressedInputStream.read(CompressedInputStream.java:79) at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:320) at org.apache.cassandra.utils.BytesReadTracker.readUnsignedShort(BytesReadTracker.java:140) at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.java:361) at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil.java:371) at org.apache.cassandra.streaming.IncomingStreamReader.streamIn(IncomingStreamReader.java:160) at org.apache.cassandra.streaming.IncomingStreamReader.read(IncomingStreamReader.java:122) at org.apache.cassandra.net.IncomingTcpConnection.stream(IncomingTcpConnection.java:238) at org.apache.cassandra.net.IncomingTcpConnection.handleStream(IncomingTcpConnection.java:178) at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:78) 2013-03-28 13:44:58.070+0100 [Thread-23] [TRACE] SSTableWriter.java(463) org.apache.cassandra.io.sstable.SSTableWriter: wrote index entry: org.apache.cassandra.db.RowIndexEntry@db766c1 at 106582 2013-03-28 13:44:58.071+0100 [Thread-23] [TRACE] SSTableWriter.java(145) org.apache.cassandra.io.sstable.SSTableWriter: wrote DecoratedKey(-4829320003365722996, 6333383266393230353964313666633136356335333437353637373735653065) at 1217942 2013-03-28 13:44:58.071+0100 [Thread-23] [TRACE] SSTableWriter.java(463) org.apache.cassandra.io.sstable.SSTableWriter: wrote index entry: org.apache.cassandra.db.RowIndexEntry@3bb0ff0 at 106628 2013-03-28 13:44:58.071+0100 [Thread-23] [TRACE] SSTableWriter.java(145) org.apache.cassandra.io.sstable.SSTableWriter: wrote DecoratedKey(-4827623571007838156, 6162376162333238393739643930336266616566393039376131366238386166) at 1218191 2013-03-28 13:44:58.071+0100 [Thread-23] [TRACE] SSTableWriter.java(463) org.apache.cassandra.io.sstable.SSTableWriter: wrote index entry: org.apache.cassandra.db.RowIndexEntry@6e135779 at 106674 2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-2-Data.db 2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-2-Filter.db 2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-2-TOC.txt 2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-2-CompressionInfo.db 2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] FileUtils.java(110) org.apache.cassandra.io.util.FileUtils: Deleting ks-cf-tmp-ib-2-Index.db 2013-03-28 13:44:58.091+0100 [Thread-23] [DEBUG] SSTable.java(154) org.apache.cassandra.io.sstable.SSTable: Deleted /path/to/cassandra/data/ks/cf/ks-cf-tmp-ib-2 2013-03-28 13:44:58.091+0100 [Thread-23] [INFO] StreamInSession.java(136) org.apache.cassandra.streaming.StreamInSession: Streaming of file /path/to/cassandra/data/ks/cf/ks-cf-ib-2-Data.db sections=131 progress=406399/1638227 - 24% for org.apache.cassandra.streaming.StreamInSession@37d40164 failed: requesting a retry. 2013-03-28 13:44:58.092+0100 [Thread-23] [DEBUG] IncomingTcpConnection.java(91) org.apache.cassandra.net.IncomingTcpConnection: IOException reading from socket; closing java.io.IOException: CRC unmatched at org.apache.cassandra.streaming.compress.CompressedInputStream.decompress(CompressedInputStream.java:111) at org.apache.cassandra.streaming.compress.CompressedInputStream.read(CompressedInputStream.java:79) at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:320) at org.apache.cassandra.utils.BytesReadTracker.readUnsignedShort(BytesReadTracker.java:140) at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.java:361) at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil.java:371) at org.apache.cassandra.streaming.IncomingStreamReader.streamIn(IncomingStreamReader.java:160) at org.apache.cassandra.streaming.IncomingStreamReader.read(IncomingStreamReader.java:122) at org.apache.cassandra.net.IncomingTcpConnection.stream(IncomingTcpConnection.java:238) at org.apache.cassandra.net.IncomingTcpConnection.handleStream(IncomingTcpConnection.java:178) at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:78) This is common for snappy and java zip: at org.apache.cassandra.streaming.compress.CompressedInputStream.read(CompressedInputStream.java:79) at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:320) at org.apache.cassandra.utils.BytesReadTracker.readUnsignedShort(BytesReadTracker.java:140) at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.java:361) at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil.java:371) at org.apache.cassandra.streaming.IncomingStreamReader.streamIn(IncomingStreamReader.java:160) at org.apache.cassandra.streaming.IncomingStreamReader.read(IncomingStreamReader.java:122) at org.apache.cassandra.net.IncomingTcpConnection.stream(IncomingTcpConnection.java:238) at org.apache.cassandra.net.IncomingTcpConnection.handleStream(IncomingTcpConnection.java:178) at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:78) When the download runs in single thread, the problem disappears.
          Hide
          ondrej.cernos Ondřej Černoš added a comment -

          How does cassandra compute the number of threads involved in streaming?

          Show
          ondrej.cernos Ondřej Černoš added a comment - How does cassandra compute the number of threads involved in streaming?
          Hide
          yukim Yuki Morishita added a comment -

          When sending file, it is single-threaded per destination.

          Show
          yukim Yuki Morishita added a comment - When sending file, it is single-threaded per destination.
          Hide
          ondrej.cernos Ondřej Černoš added a comment -

          How does this information match the observed behaviour? I can clearly see two threads downloading the file.

          Show
          ondrej.cernos Ondřej Černoš added a comment - How does this information match the observed behaviour? I can clearly see two threads downloading the file.
          Hide
          yukim Yuki Morishita added a comment -

          CompressedFileStreamTask is not sending the right part of the file when using inter-node encryption, and that causes various IOException described here.

          Patch attached for fix.

          Show
          yukim Yuki Morishita added a comment - CompressedFileStreamTask is not sending the right part of the file when using inter-node encryption, and that causes various IOException described here. Patch attached for fix.
          Hide
          iamaleksey Aleksey Yeschenko added a comment -

          +1

          Show
          iamaleksey Aleksey Yeschenko added a comment - +1
          Hide
          yukim Yuki Morishita added a comment -

          Committed. Thanks!

          Show
          yukim Yuki Morishita added a comment - Committed. Thanks!
          Hide
          jan.chochol Jan Chochol added a comment -

          Hi everyone, I am working with Ondrej on same problem.
          I just looked to patch (git commit cc6429e2722e764dce8cad77660732146ed596ab) and I am not sure that it is exactly correct.
          Problematic situation is, when length > CHUNK_SIZE (in CompressedFileStreamTask.stream()). In this case data will be sent in more chunks, but before every chunk this code will be executed:

          file.seek(section.left);
          

          Sending only first chunk every time will probably lead to described error.
          I would suggest to move file.seek before beginning of while cycle (than file pointer will be moved by readFully) or change mentioned code to

          file.seek(section.left + bytesTransferred);
          
          Show
          jan.chochol Jan Chochol added a comment - Hi everyone, I am working with Ondrej on same problem. I just looked to patch (git commit cc6429e2722e764dce8cad77660732146ed596ab) and I am not sure that it is exactly correct. Problematic situation is, when length > CHUNK_SIZE (in CompressedFileStreamTask.stream() ). In this case data will be sent in more chunks, but before every chunk this code will be executed: file.seek(section.left); Sending only first chunk every time will probably lead to described error. I would suggest to move file.seek before beginning of while cycle (than file pointer will be moved by readFully ) or change mentioned code to file.seek(section.left + bytesTransferred);
          Hide
          krummas Marcus Eriksson added a comment -

          that sounds and looks reasonable, reopening to let @yukim have a look

          Show
          krummas Marcus Eriksson added a comment - that sounds and looks reasonable, reopening to let @yukim have a look
          Hide
          ondrej.cernos Ondřej Černoš added a comment -

          I tested the patch and verified it doesn't fix the issue.

          Show
          ondrej.cernos Ondřej Černoš added a comment - I tested the patch and verified it doesn't fix the issue.
          Hide
          ondrej.cernos Ondřej Černoš added a comment -

          I tried Jan's proposal to move the seek out of the while loop and let the pointer be moved by the readFully method call, but with no luck. I'll let someone with more Cassandra internals knowledge to dive into this.

          Show
          ondrej.cernos Ondřej Černoš added a comment - I tried Jan's proposal to move the seek out of the while loop and let the pointer be moved by the readFully method call, but with no luck. I'll let someone with more Cassandra internals knowledge to dive into this.
          Hide
          yukim Yuki Morishita added a comment -

          Jan, Ondřej,

          Thanks for reporting.
          What I wanted to do was to position the file pointer to the beginning of section for each loop, as uncompressed version do.
          I attached two patches (-1.2.3 to apply for 1.2.3 release and -1.2 for current 1.2 branch). Can you try these?

          Show
          yukim Yuki Morishita added a comment - Jan, Ondřej, Thanks for reporting. What I wanted to do was to position the file pointer to the beginning of section for each loop, as uncompressed version do. I attached two patches (-1.2.3 to apply for 1.2.3 release and -1.2 for current 1.2 branch). Can you try these?
          Hide
          ondrej.cernos Ondřej Černoš added a comment - - edited

          This patch seems to work. So the issue may be resolved now. Thanks!

          Show
          ondrej.cernos Ondřej Černoš added a comment - - edited This patch seems to work. So the issue may be resolved now. Thanks!
          Hide
          yukim Yuki Morishita added a comment -

          Committed, thanks!

          Show
          yukim Yuki Morishita added a comment - Committed, thanks!
          Hide
          mikelococo Mike added a comment -

          I don't think I see any code changes in the 1.1.x branch as a result of this bug. Does the bug not apply to 1.1.x (aka, it was introduced in the 1.2.0 streaming refactor?), or does 1.1.12 (and 1.1.9, on which Datastax Enterprise is based) still suffer from this?

          Show
          mikelococo Mike added a comment - I don't think I see any code changes in the 1.1.x branch as a result of this bug. Does the bug not apply to 1.1.x (aka, it was introduced in the 1.2.0 streaming refactor?), or does 1.1.12 (and 1.1.9, on which Datastax Enterprise is based) still suffer from this?

            People

            • Assignee:
              yukim Yuki Morishita
              Reporter:
              ondrej.cernos Ondřej Černoš
              Reviewer:
              Aleksey Yeschenko
            • Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development