cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Paulo Motta (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CASSANDRA-11286) streaming socket never times out
Date Tue, 08 Mar 2016 19:24:40 GMT

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

Paulo Motta commented on CASSANDRA-11286:
-----------------------------------------

There is a relatively common scenario when the receiver receives a {{COMPLETE}} message from
the sender, changes its state to {{WAIT_COMPLETE}} and then the {{IncomingMessageHandler}}
blocks on the socket again, and meanwhile the {{OnCompletionRunnable}} finishes processing
the received stream and closes the session via {{maybeCompleted()}}. Even though the session
is terminated correctly on both sides, after {{streaming_socket_timeout_in_ms}} the user may
get a harmless but scary {{StreamSocketTimeout}} log message from the previously blocked socket
(got this in dtests a few times). In order to fix this I updated the patch to close the {{OutgoingStreamHandler}}
after sending the last {{COMPLETE}} message, and the {{IncomingStreamHandler}} after receiving
the last {{COMPLETE}} message, so all resources are properly released.

Below is an example of this scenario:
{noformat}
DEBUG [STREAM-IN-/127.0.0.1] 2016-03-08 15:31:18,632 ConnectionHandler.java:269 - [Stream
#f19e82b0-e55b-11e5-9a50-f59bd42ef741] Received Complete
DEBUG [STREAM-OUT-/127.0.0.1] 2016-03-08 15:31:19,004 ConnectionHandler.java:341 - [Stream
#f19e82b0-e55b-11e5-9a50-f59bd42ef741] Sending Complete
DEBUG [StreamReceiveTask:1] 2016-03-08 15:31:19,004 ConnectionHandler.java:110 - [Stream #f19e82b0-e55b-11e5-9a50-f59bd42ef741]
Closing stream connection handler on /127.0.0.1
INFO  [StreamReceiveTask:1] 2016-03-08 15:31:19,005 StreamResultFuture.java:182 - [Stream
#f19e82b0-e55b-11e5-9a50-f59bd42ef741] Session with /127.0.0.1 is complete
INFO  [StreamReceiveTask:1] 2016-03-08 15:31:19,025 StreamResultFuture.java:214 - [Stream
#f19e82b0-e55b-11e5-9a50-f59bd42ef741] All sessions completed

.... {{streaming_socket_timeout}} passes...

ERROR [STREAM-IN-/127.0.0.1] 2016-03-08 15:31:19,638 StreamSession.java:524 - [Stream #f19e82b0-e55b-11e5-9a50-f59bd42ef741]
Streaming error occurred
java.net.SocketTimeoutException: null
        at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:211) ~[na:1.8.0_66]
        at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103) ~[na:1.8.0_66]
        at java.nio.channels.Channels$ReadableByteChannelImpl.read(Channels.java:385) ~[na:1.8.0_66]
        at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:53)
~[main/:na]
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:268)
~[main/:na]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_66]
{noformat}

I also noticed that {{replace_address_test.TestReplaceAddress.replace_with_reset_resume_state_test}}
(CASSANDRA-11246) and {{replace_address_test.TestReplaceAddress.resumable_replace_test}} was
failing for the same reason as {{bootstrap_test.py:TestBootstrap.resumable_bootstrap_test}}
(CASSANDRA-10912), so I applied the fix of CASSANDRA-10167 (decrease the socket timeout) to
the [dtest PR|https://github.com/riptano/cassandra-dtest/pull/841], which should avoid hanging
on these tests due to default {{streaming_socket_timeout_in_ms}} of 1 hour.

I rebased and updated branches and resubmitted tests:
||2.1||2.2||3.0||3.5||trunk||dtest||
|[branch|https://github.com/apache/cassandra/compare/cassandra-2.1...pauloricardomg:2.1-11286]|[branch|https://github.com/apache/cassandra/compare/cassandra-2.2...pauloricardomg:2.2-11286]|[branch|https://github.com/apache/cassandra/compare/cassandra-3.0...pauloricardomg:3.0-11286]|[branch|https://github.com/apache/cassandra/compare/cassandra-3.5...pauloricardomg:3.5-11286]|[branch|https://github.com/apache/cassandra/compare/trunk...pauloricardomg:trunk-11286]|[branch|https://github.com/riptano/cassandra-dtest/compare/master...pauloricardomg:11286-dtest]|
|[testall|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-2.1-11286-testall/lastCompletedBuild/testReport/]|[testall|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-2.2-11286-testall/lastCompletedBuild/testReport/]|[testall|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-3.0-11286-testall/lastCompletedBuild/testReport/]|[testall|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-3.5-11286-testall/lastCompletedBuild/testReport/]|[testall|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-trunk-11286-testall/lastCompletedBuild/testReport/]|
|[dtest|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-2.1-11286-dtest/lastCompletedBuild/testReport/]|[dtest|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-2.2-11286-dtest/lastCompletedBuild/testReport/]|[dtest|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-3.0-11286-dtest/lastCompletedBuild/testReport/]|[dtest|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-3.5-11286-dtest/lastCompletedBuild/testReport/]|[dtest|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-trunk-11286-dtest/lastCompletedBuild/testReport/]|


> streaming socket never times out
> --------------------------------
>
>                 Key: CASSANDRA-11286
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-11286
>             Project: Cassandra
>          Issue Type: Bug
>          Components: Streaming and Messaging
>            Reporter: Paulo Motta
>            Assignee: Paulo Motta
>
> While trying to reproduce CASSANDRA-8343 I was not able to trigger a {{SocketTimeoutException}}
by adding an artificial sleep longer than {{streaming_socket_timeout_in_ms}}.
> After investigation, I detected two problems:
> * {{ReadableByteChannel}} creation via {{socket.getChannel()}}, as done in {{ConnectionHandler.getReadChannel(socket)}},
does not respect {{socket.setSoTimeout()}}, as explained in this [blog post|https://technfun.wordpress.com/2009/01/29/networking-in-java-non-blocking-nio-blocking-nio-and-io/]
> ** bq. The only difference between “blocking NIO” and “NIO wrapped around IO”
is that you can’t use socket timeout with SocketChannels. Why ? Read a javadoc for setSocketTimeout().
It says that this timeout is used only by streams.
> * {{socketSoTimeout}} is never set on "follower" side, only on initiator side via {{DefaultConnectionFactory.createConnection(peer)}}.
> This may cause streaming to hang indefinitely, as exemplified by CASSANDRA-8621:
> bq. For the scenario that prompted this ticket, it appeared that the streaming process
was completely stalled. One side of the stream (the sender side) had an exception that appeared
to be a connection reset. The receiving side appeared to think that the connection was still
active, at least in terms of the netstats reported by nodetool. We were unable to verify whether
this was specifically the case in terms of connected sockets due to the fact that there were
multiple streams for those peers, and there is no simple way to correlate a specific stream
to a tcp session.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message