cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ondřej Černoš (JIRA) <j...@apache.org>
Subject [jira] [Commented] (CASSANDRA-5391) SSL problems with inter-DC communication
Date Thu, 28 Mar 2013 14:46:20 GMT

    [ https://issues.apache.org/jira/browse/CASSANDRA-5391?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13616307#comment-13616307
] 

Ondřej Černoš commented on CASSANDRA-5391:
------------------------------------------

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:

{noformat}
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
{noformat}

And here is the result grepped on the two threads:

{noformat}
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)
{noformat}

This is common for snappy and java zip:

{noformat}
	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)
{noformat}

When the download runs in single thread, the problem disappears.
                
> SSL problems with inter-DC communication
> ----------------------------------------
>
>                 Key: CASSANDRA-5391
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-5391
>             Project: Cassandra
>          Issue Type: Bug
>          Components: Core
>    Affects Versions: 1.2.3
>         Environment: $ /etc/alternatives/jre_1.6.0/bin/java -version
> java version "1.6.0_23"
> Java(TM) SE Runtime Environment (build 1.6.0_23-b05)
> Java HotSpot(TM) 64-Bit Server VM (build 19.0-b09, mixed mode)
> $ uname -a
> Linux hostname 2.6.32-358.2.1.el6.x86_64 #1 SMP Tue Mar 12 14:18:09 CDT 2013 x86_64 x86_64
x86_64 GNU/Linux
> $ cat /etc/redhat-release 
> Scientific Linux release 6.3 (Carbon)
> $ facter | grep ec2
> ...
> ec2_placement => availability_zone=us-east-1d
> ...
> $ rpm -qi cassandra
> cassandra-1.2.3-1.el6.cmp1.noarch
> (custom built rpm from cassandra tarball distribution)
>            Reporter: Ondřej Černoš
>            Assignee: T Jake Luciani
>            Priority: Blocker
>
> 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:
> {noformat}
> 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)
> {noformat}
> 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.
> {noformat}
> 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
> {noformat}
> 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.
> {noformat}
> 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)
> {noformat}

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

Mime
View raw message