[jira] [Commented] (CASSANDRA-8343) Secondary index creation causes moves/bootstraps to fail
[
https://issues.apache.org/jira/browse/CASSANDRA-8343?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15274123#comment-15274123
]
Paulo Motta commented on CASSANDRA-8343:
while trying to reproduce this once more on 2.2-HEAD before submitting a final
patch I noticed that bootstrap was not failing if secondary index creation
takes longer than {{streaming_socket_timeout_in_ms}}, even though the stream
session failed on sender side, which closes the socket, but completes
successfully on the bootstrapping node.
the strange thing is that while the socket was closed on the sender side after
{{streaming_socket_timeout_in_ms}}, the receiver still sent the last
{{complete}} message on the "closed" socket without failures. I'll see what's
going on.
> Secondary index creation causes moves/bootstraps to fail
>
>
> Key: CASSANDRA-8343
> URL: https://issues.apache.org/jira/browse/CASSANDRA-8343
> Project: Cassandra
> Issue Type: Bug
>Reporter: Michael Frisch
>Assignee: Paulo Motta
>
> Node moves/bootstraps are failing if the stream timeout is set to a value in
> which secondary index creation cannot complete. This happens because at the
> end of the very last stream the StreamInSession.closeIfFinished() function
> calls maybeBuildSecondaryIndexes on every column family. If the stream time
> + all CF's index creation takes longer than your stream timeout then the
> socket closes from the sender's side, the receiver of the stream tries to
> write to said socket because it's not null, an IOException is thrown but not
> caught in closeIfFinished(), the exception is caught somewhere and not
> logged, AbstractStreamSession.close() is never called, and the CountDownLatch
> is never decremented. This causes the move/bootstrap to continue forever
> until the node is restarted.
> This problem of stream time + secondary index creation time exists on
> decommissioning/unbootstrap as well but since it's on the sending side the
> timeout triggers the onFailure() callback which does decrement the
> CountDownLatch leading to completion.
> A cursory glance at the 2.0 code leads me to believe this problem would exist
> there as well.
> Temporary workaround: set a really high/infinite stream timeout.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Commented] (CASSANDRA-8343) Secondary index creation causes moves/bootstraps to fail
[
https://issues.apache.org/jira/browse/CASSANDRA-8343?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15280561#comment-15280561
]
Paulo Motta commented on CASSANDRA-8343:
This also happens when streaming large files (see CASSANDRA-11345), so a
Keep-Alive message from the sender will probably be necessary during the whole
streaming process (not only after {{WAIT_COMPLETE}} state.
While the streaming protocol version does not change, we could probably reuse
the "received" message, with a special file seq num (-1) to represent a keep
alive message.
> Secondary index creation causes moves/bootstraps to fail
>
>
> Key: CASSANDRA-8343
> URL: https://issues.apache.org/jira/browse/CASSANDRA-8343
> Project: Cassandra
> Issue Type: Bug
>Reporter: Michael Frisch
>Assignee: Paulo Motta
>
> Node moves/bootstraps are failing if the stream timeout is set to a value in
> which secondary index creation cannot complete. This happens because at the
> end of the very last stream the StreamInSession.closeIfFinished() function
> calls maybeBuildSecondaryIndexes on every column family. If the stream time
> + all CF's index creation takes longer than your stream timeout then the
> socket closes from the sender's side, the receiver of the stream tries to
> write to said socket because it's not null, an IOException is thrown but not
> caught in closeIfFinished(), the exception is caught somewhere and not
> logged, AbstractStreamSession.close() is never called, and the CountDownLatch
> is never decremented. This causes the move/bootstrap to continue forever
> until the node is restarted.
> This problem of stream time + secondary index creation time exists on
> decommissioning/unbootstrap as well but since it's on the sending side the
> timeout triggers the onFailure() callback which does decrement the
> CountDownLatch leading to completion.
> A cursory glance at the 2.0 code leads me to believe this problem would exist
> there as well.
> Temporary workaround: set a really high/infinite stream timeout.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Commented] (CASSANDRA-8343) Secondary index creation causes moves/bootstraps to fail
[ https://issues.apache.org/jira/browse/CASSANDRA-8343?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15289672#comment-15289672 ] Paulo Motta commented on CASSANDRA-8343: Closing as duplicate of more general ticket CASSANDRA-11839. > Secondary index creation causes moves/bootstraps to fail > > > Key: CASSANDRA-8343 > URL: https://issues.apache.org/jira/browse/CASSANDRA-8343 > Project: Cassandra > Issue Type: Bug >Reporter: Michael Frisch >Assignee: Paulo Motta > > Node moves/bootstraps are failing if the stream timeout is set to a value in > which secondary index creation cannot complete. This happens because at the > end of the very last stream the StreamInSession.closeIfFinished() function > calls maybeBuildSecondaryIndexes on every column family. If the stream time > + all CF's index creation takes longer than your stream timeout then the > socket closes from the sender's side, the receiver of the stream tries to > write to said socket because it's not null, an IOException is thrown but not > caught in closeIfFinished(), the exception is caught somewhere and not > logged, AbstractStreamSession.close() is never called, and the CountDownLatch > is never decremented. This causes the move/bootstrap to continue forever > until the node is restarted. > This problem of stream time + secondary index creation time exists on > decommissioning/unbootstrap as well but since it's on the sending side the > timeout triggers the onFailure() callback which does decrement the > CountDownLatch leading to completion. > A cursory glance at the 2.0 code leads me to believe this problem would exist > there as well. > Temporary workaround: set a really high/infinite stream timeout. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (CASSANDRA-8343) Secondary index creation causes moves/bootstraps to fail
[ https://issues.apache.org/jira/browse/CASSANDRA-8343?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15218432#comment-15218432 ] Yuki Morishita commented on CASSANDRA-8343: --- Patch makes StreamTransferTaskTest fail but I guess we just need test update. Otherwise, it looks good to me. Can you update the patch with other branches too? > Secondary index creation causes moves/bootstraps to fail > > > Key: CASSANDRA-8343 > URL: https://issues.apache.org/jira/browse/CASSANDRA-8343 > Project: Cassandra > Issue Type: Bug >Reporter: Michael Frisch >Assignee: Paulo Motta > > Node moves/bootstraps are failing if the stream timeout is set to a value in > which secondary index creation cannot complete. This happens because at the > end of the very last stream the StreamInSession.closeIfFinished() function > calls maybeBuildSecondaryIndexes on every column family. If the stream time > + all CF's index creation takes longer than your stream timeout then the > socket closes from the sender's side, the receiver of the stream tries to > write to said socket because it's not null, an IOException is thrown but not > caught in closeIfFinished(), the exception is caught somewhere and not > logged, AbstractStreamSession.close() is never called, and the CountDownLatch > is never decremented. This causes the move/bootstrap to continue forever > until the node is restarted. > This problem of stream time + secondary index creation time exists on > decommissioning/unbootstrap as well but since it's on the sending side the > timeout triggers the onFailure() callback which does decrement the > CountDownLatch leading to completion. > A cursory glance at the 2.0 code leads me to believe this problem would exist > there as well. > Temporary workaround: set a really high/infinite stream timeout. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (CASSANDRA-8343) Secondary index creation causes moves/bootstraps to fail
[
https://issues.apache.org/jira/browse/CASSANDRA-8343?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15144718#comment-15144718
]
Paulo Motta commented on CASSANDRA-8343:
Surprisingly enough I didn't manage to reproduce this issue in 2.1 because the
{{streaming_socket_timeout}} parameter was not being enforced due to the use of
a {{ReadableByteChannel}} created via {{socket.getChannel()}}, which never
times out on reads (see [this
article|https://technfun.wordpress.com/2009/01/29/networking-in-java-non-blocking-nio-blocking-nio-and-io/]
for background). The workaround is to create the {{ReadableByteChannel}} via
{{Channels.newChannel(socket.getInputStream())}} instead, so the socket
{{SO_TIMEOUT}} is respected.
Even after this fix, the socket {{SO_TIMEOUT}} was never being set on the
receiving side, so I also set while attaching the socket on the receiving side.
After the previous fixes, I managed to reproduce this issue on a [bootstrap
dtest|https://github.com/pauloricardomg/cassandra-dtest/commit/301e332758b3873d2bb61259343375107caf437b]
by introducing a sleep delay (via a system property) on the
{{OnCompletionRunnable}} larger than {{streaming_socket_timeout}}.
This problem will probably happen more often on 3.0 because of MVs, since
they're rebuilt by the receiving node in the end of the stream session.
I think we should remain finishing the stream session only after the secondary
indexes/MVs are rebuilt to avoid leaving the node in a inconsistent state in
case the rebuild fails after the session is completed.
The proposed solution is to introduce a {{KeepAlive}} message and send a keep
alive message to the peer after reaching the {{WAIT_COMPLETE}} state every
{{streaming_socket_timeout/2}}, to ensure the socket will remain fresh and will
not throw a {{SocketTimeoutException}} and fail the stream session.
I initially created a fix for 2.1 (even though it's near EOL, I think
{{streaming_socket_timeout}} not working is critical enough to be fixed on
2.1), and after review I will create patch for other versions.
||2.1||dtest||
|[branch|https://github.com/apache/cassandra/compare/cassandra-2.1...pauloricardomg:2.1-8343]|[branch|https://github.com/riptano/cassandra-dtest/compare/master...pauloricardomg:8343]|
|[testall|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-2.1-8343-testall/lastCompletedBuild/testReport/]|
|[dtest|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-2.1-8343-dtest/lastCompletedBuild/testReport/]|
> Secondary index creation causes moves/bootstraps to fail
>
>
> Key: CASSANDRA-8343
> URL: https://issues.apache.org/jira/browse/CASSANDRA-8343
> Project: Cassandra
> Issue Type: Bug
>Reporter: Michael Frisch
>Assignee: Paulo Motta
>
> Node moves/bootstraps are failing if the stream timeout is set to a value in
> which secondary index creation cannot complete. This happens because at the
> end of the very last stream the StreamInSession.closeIfFinished() function
> calls maybeBuildSecondaryIndexes on every column family. If the stream time
> + all CF's index creation takes longer than your stream timeout then the
> socket closes from the sender's side, the receiver of the stream tries to
> write to said socket because it's not null, an IOException is thrown but not
> caught in closeIfFinished(), the exception is caught somewhere and not
> logged, AbstractStreamSession.close() is never called, and the CountDownLatch
> is never decremented. This causes the move/bootstrap to continue forever
> until the node is restarted.
> This problem of stream time + secondary index creation time exists on
> decommissioning/unbootstrap as well but since it's on the sending side the
> timeout triggers the onFailure() callback which does decrement the
> CountDownLatch leading to completion.
> A cursory glance at the 2.0 code leads me to believe this problem would exist
> there as well.
> Temporary workaround: set a really high/infinite stream timeout.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Commented] (CASSANDRA-8343) Secondary index creation causes moves/bootstraps to fail
[
https://issues.apache.org/jira/browse/CASSANDRA-8343?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15144731#comment-15144731
]
Paulo Motta commented on CASSANDRA-8343:
It's also important to note that currently if the secondary index rebuild takes
longer than {{streaming_socket_timeout_in_ms}} the stream session will fail
(and not hang as described in this ticket report) due to CASSANDRA-10774.
> Secondary index creation causes moves/bootstraps to fail
>
>
> Key: CASSANDRA-8343
> URL: https://issues.apache.org/jira/browse/CASSANDRA-8343
> Project: Cassandra
> Issue Type: Bug
>Reporter: Michael Frisch
>Assignee: Paulo Motta
>
> Node moves/bootstraps are failing if the stream timeout is set to a value in
> which secondary index creation cannot complete. This happens because at the
> end of the very last stream the StreamInSession.closeIfFinished() function
> calls maybeBuildSecondaryIndexes on every column family. If the stream time
> + all CF's index creation takes longer than your stream timeout then the
> socket closes from the sender's side, the receiver of the stream tries to
> write to said socket because it's not null, an IOException is thrown but not
> caught in closeIfFinished(), the exception is caught somewhere and not
> logged, AbstractStreamSession.close() is never called, and the CountDownLatch
> is never decremented. This causes the move/bootstrap to continue forever
> until the node is restarted.
> This problem of stream time + secondary index creation time exists on
> decommissioning/unbootstrap as well but since it's on the sending side the
> timeout triggers the onFailure() callback which does decrement the
> CountDownLatch leading to completion.
> A cursory glance at the 2.0 code leads me to believe this problem would exist
> there as well.
> Temporary workaround: set a really high/infinite stream timeout.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Commented] (CASSANDRA-8343) Secondary index creation causes moves/bootstraps to fail
[
https://issues.apache.org/jira/browse/CASSANDRA-8343?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15147092#comment-15147092
]
Sylvain Lebresne commented on CASSANDRA-8343:
-
bq. The proposed solution is to introduce a {{KeepAlive}} message
How does that work in term of backward compatibility?
> Secondary index creation causes moves/bootstraps to fail
>
>
> Key: CASSANDRA-8343
> URL: https://issues.apache.org/jira/browse/CASSANDRA-8343
> Project: Cassandra
> Issue Type: Bug
>Reporter: Michael Frisch
>Assignee: Paulo Motta
>
> Node moves/bootstraps are failing if the stream timeout is set to a value in
> which secondary index creation cannot complete. This happens because at the
> end of the very last stream the StreamInSession.closeIfFinished() function
> calls maybeBuildSecondaryIndexes on every column family. If the stream time
> + all CF's index creation takes longer than your stream timeout then the
> socket closes from the sender's side, the receiver of the stream tries to
> write to said socket because it's not null, an IOException is thrown but not
> caught in closeIfFinished(), the exception is caught somewhere and not
> logged, AbstractStreamSession.close() is never called, and the CountDownLatch
> is never decremented. This causes the move/bootstrap to continue forever
> until the node is restarted.
> This problem of stream time + secondary index creation time exists on
> decommissioning/unbootstrap as well but since it's on the sending side the
> timeout triggers the onFailure() callback which does decrement the
> CountDownLatch leading to completion.
> A cursory glance at the 2.0 code leads me to believe this problem would exist
> there as well.
> Temporary workaround: set a really high/infinite stream timeout.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Commented] (CASSANDRA-8343) Secondary index creation causes moves/bootstraps to fail
[
https://issues.apache.org/jira/browse/CASSANDRA-8343?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15150311#comment-15150311
]
Sylvain Lebresne commented on CASSANDRA-8343:
-
I'm not super familiar with how the streaming protocol number is used. If there
is some protocol version negotiations between nodes that make it possible to
bump the number without breaking any backward compatibility, then that would be
fine for trunk (well, assuming we do carefully test this). Otherwise, we'd have
to wait for 4.0.
bq. we've had this problem since forever \[...\] there is the workaround of
increasing {{streaming_socket_timeout}}
I agree that this probably mean it's not worth doing too risky changes for this
before trunk. But really, it feels to me that the main problem is how the code
handle this kind of problem. Assuming we probably surface the timeout on the
sending side, there is not reason not to properly close the session and move on
on the receiving side when this happen (we could still log an error or warning
on that receiving side explaining what happens (and that if the sending
timeouted, the user may want to increase {{streaming_socket_timeout}})). We can
also document that {{streaming_socket_timeout}} should be high enough to let
2ndary index/MVs be built in the yaml.
Imo, if we handle the case better (by not breaking anything but logging enough
info that the user understand what happened and that this is really not a big
deal), it's fine if we only fix it properly in 4.0 (we do need to have a better
solution eventually of course).
> Secondary index creation causes moves/bootstraps to fail
>
>
> Key: CASSANDRA-8343
> URL: https://issues.apache.org/jira/browse/CASSANDRA-8343
> Project: Cassandra
> Issue Type: Bug
>Reporter: Michael Frisch
>Assignee: Paulo Motta
>
> Node moves/bootstraps are failing if the stream timeout is set to a value in
> which secondary index creation cannot complete. This happens because at the
> end of the very last stream the StreamInSession.closeIfFinished() function
> calls maybeBuildSecondaryIndexes on every column family. If the stream time
> + all CF's index creation takes longer than your stream timeout then the
> socket closes from the sender's side, the receiver of the stream tries to
> write to said socket because it's not null, an IOException is thrown but not
> caught in closeIfFinished(), the exception is caught somewhere and not
> logged, AbstractStreamSession.close() is never called, and the CountDownLatch
> is never decremented. This causes the move/bootstrap to continue forever
> until the node is restarted.
> This problem of stream time + secondary index creation time exists on
> decommissioning/unbootstrap as well but since it's on the sending side the
> timeout triggers the onFailure() callback which does decrement the
> CountDownLatch leading to completion.
> A cursory glance at the 2.0 code leads me to believe this problem would exist
> there as well.
> Temporary workaround: set a really high/infinite stream timeout.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Commented] (CASSANDRA-8343) Secondary index creation causes moves/bootstraps to fail
[
https://issues.apache.org/jira/browse/CASSANDRA-8343?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15154892#comment-15154892
]
Paulo Motta commented on CASSANDRA-8343:
Thanks for the input [~slebresne]!
I created a simpler version of the patch that does not involve adding a new
message to the streaming protocol but may tolerate an index rebuild larger than
{{streaming_socket_timeout}}.
The basic idea is to tolerate up to 3 socket timeouts on the sender side if
it's on the {{WAIT_COMPLETE}} state, giving a total of
{{3*streaming_socket_timeout}} for the receiver to process the data which would
be 3 hours with the current default, which IMO should be sufficient for most
scenarios. In case there are more than 3 consecutive socket timeouts an
informative message is logged asking the user to increase the value of
{{streaming_socket_timeout}} (as suggested by Sylvain) and the stream session
is failed. Below is an example of this new approach:
{noformat}
debug.log:DEBUG [STREAM-OUT-/127.0.0.2] 2016-02-19 18:00:09,947
ConnectionHandler.java:351 - [Stream #c2b5c6c0-d74b-11e5-a490-dfb88388eec7]
Sending Complete
debug.log:DEBUG [STREAM-IN-/127.0.0.2] 2016-02-19 18:00:10,948
StreamSession.java:221 - [Stream #c2b5c6c0-d74b-11e5-a490-dfb88388eec7]
Received socket timeout but will ignore it because stream session is on
WAIT_COMPLETE state, so other peer might be still processing received data
beforereplying to this node. Ignored 1 out of 3 times.
debug.log:DEBUG [STREAM-IN-/127.0.0.2] 2016-02-19 18:00:11,948
StreamSession.java:221 - [Stream #c2b5c6c0-d74b-11e5-a490-dfb88388eec7]
Received socket timeout but will ignore it because stream session is on
WAIT_COMPLETE state, so other peer might be still processing received data
beforereplying to this node. Ignored 2 out of 3 times.
debug.log:DEBUG [STREAM-IN-/127.0.0.2] 2016-02-19 18:00:12,096
ConnectionHandler.java:273 - [Stream #c2b5c6c0-d74b-11e5-a490-dfb88388eec7]
Received Complete
debug.log:DEBUG [STREAM-IN-/127.0.0.2] 2016-02-19 18:00:12,096
ConnectionHandler.java:112 - [Stream #c2b5c6c0-d74b-11e5-a490-dfb88388eec7]
Closing stream connection handler on /127.0.0.2
{noformat}
IMO this should be a good enough approach for the time being and we can revisit
adding a new {{KeepAlive}} message if necessary when bumping the streaming
message version later. We could also revisit that in the context of
CASSANDRA-8621 (streaming retry on socket timeout).
I also closed the outgoing message handler on the sender side after the
"complete" message is sent, and similarly closed the incoming message handler
on the receiving side after receiving the "complete" message since they are no
longer necessary.
Below is new patch and tests:
||2.2||dtest||
|[branch|https://github.com/apache/cassandra/compare/cassandra-2.2...pauloricardomg:2.2-8343]|[branch|https://github.com/riptano/cassandra-dtest/compare/master...pauloricardomg:8343]|
|[testall|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-2.2-8343-testall/lastCompletedBuild/testReport/]|
|[dtest|http://cassci.datastax.com/view/Dev/view/paulomotta/job/pauloricardomg-2.2-8343-dtest/lastCompletedBuild/testReport/]|
WDYT of this approach [~yukim]?
> Secondary index creation causes moves/bootstraps to fail
>
>
> Key: CASSANDRA-8343
> URL: https://issues.apache.org/jira/browse/CASSANDRA-8343
> Project: Cassandra
> Issue Type: Bug
>Reporter: Michael Frisch
>Assignee: Paulo Motta
>
> Node moves/bootstraps are failing if the stream timeout is set to a value in
> which secondary index creation cannot complete. This happens because at the
> end of the very last stream the StreamInSession.closeIfFinished() function
> calls maybeBuildSecondaryIndexes on every column family. If the stream time
> + all CF's index creation takes longer than your stream timeout then the
> socket closes from the sender's side, the receiver of the stream tries to
> write to said socket because it's not null, an IOException is thrown but not
> caught in closeIfFinished(), the exception is caught somewhere and not
> logged, AbstractStreamSession.close() is never called, and the CountDownLatch
> is never decremented. This causes the move/bootstrap to continue forever
> until the node is restarted.
> This problem of stream time + secondary index creation time exists on
> decommissioning/unbootstrap as well but since it's on the sending side the
> timeout triggers the onFailure() callback which does decrement the
> CountDownLatch leading to completion.
> A cursory glance at the 2.0 code leads me to believe this problem would exist
> there as well.
> Temporary workaround: set a really high/infinite stream timeout.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
