Jim Witschey created CASSANDRA-11611:
----------------------------------------
Summary: dtest failure in
topology_test.TestTopology.crash_during_decommission_test
Key: CASSANDRA-11611
URL: https://issues.apache.org/jira/browse/CASSANDRA-11611
Project: Cassandra
Issue Type: Test
Reporter: Jim Witschey
Assignee: DS Test Eng
Looks like some kind of streaming error. Example failure:
http://cassci.datastax.com/job/trunk_dtest_win32/382/testReport/topology_test/TestTopology/crash_during_decommission_test
Failed on CassCI build trunk_dtest_win32 #382
{code}
Error Message
Unexpected error in log, see stdout
-------------------- >> begin captured logging << --------------------
dtest: DEBUG: cluster ccm directory: d:\temp\dtest-ce_wos
dtest: DEBUG: Custom init_config not found. Setting defaults.
dtest: DEBUG: Done setting configuration options:
{ 'initial_token': None,
'num_tokens': '32',
'phi_convict_threshold': 5,
'range_request_timeout_in_ms': 10000,
'read_request_timeout_in_ms': 10000,
'request_timeout_in_ms': 10000,
'truncate_request_timeout_in_ms': 10000,
'write_request_timeout_in_ms': 10000}
dtest: DEBUG: Status as reported by node 127.0.0.2
dtest: DEBUG: Datacenter: datacenter1
========================
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
UN 127.0.0.1 98.73 KiB 32 78.4%
b8c55c71-bf3d-462b-8c17-3c88d7ac2284 rack1
UN 127.0.0.2 162.38 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1
UN 127.0.0.3 98.71 KiB 32 55.7%
3a4529a3-dc7f-445c-aec3-94417c920fdf rack1
dtest: DEBUG: Restarting node2
dtest: DEBUG: Status as reported by node 127.0.0.2
dtest: DEBUG: Datacenter: datacenter1
========================
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
UL 127.0.0.1 98.73 KiB 32 78.4%
b8c55c71-bf3d-462b-8c17-3c88d7ac2284 rack1
UN 127.0.0.2 222.26 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1
UN 127.0.0.3 98.71 KiB 32 55.7%
3a4529a3-dc7f-445c-aec3-94417c920fdf rack1
dtest: DEBUG: Restarting node2
dtest: DEBUG: Status as reported by node 127.0.0.2
dtest: DEBUG: Datacenter: datacenter1
========================
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
UL 127.0.0.1 174.2 KiB 32 78.4%
b8c55c71-bf3d-462b-8c17-3c88d7ac2284 rack1
UN 127.0.0.2 336.69 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1
UN 127.0.0.3 116.7 KiB 32 55.7%
3a4529a3-dc7f-445c-aec3-94417c920fdf rack1
dtest: DEBUG: Restarting node2
dtest: DEBUG: Status as reported by node 127.0.0.2
dtest: DEBUG: Datacenter: datacenter1
========================
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
UL 127.0.0.1 174.2 KiB 32 78.4%
b8c55c71-bf3d-462b-8c17-3c88d7ac2284 rack1
UN 127.0.0.2 360.82 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1
UN 127.0.0.3 116.7 KiB 32 55.7%
3a4529a3-dc7f-445c-aec3-94417c920fdf rack1
dtest: DEBUG: Restarting node2
dtest: DEBUG: Status as reported by node 127.0.0.2
dtest: DEBUG: Datacenter: datacenter1
========================
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
UL 127.0.0.1 174.2 KiB 32 78.4%
b8c55c71-bf3d-462b-8c17-3c88d7ac2284 rack1
UN 127.0.0.2 240.54 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1
UN 127.0.0.3 116.7 KiB 32 55.7%
3a4529a3-dc7f-445c-aec3-94417c920fdf rack1
dtest: DEBUG: Restarting node2
dtest: DEBUG: Decommission failed with exception: Nodetool command
'D:\jenkins\workspace\trunk_dtest_win32\cassandra\bin\nodetool.bat -h localhost
-p 7100 decommission' failed; exit status: 2; stderr: error: Stream failed
-- StackTrace --
org.apache.cassandra.streaming.StreamException: Stream failed
at
org.apache.cassandra.streaming.management.StreamEventJMXNotifier.onFailure(StreamEventJMXNotifier.java:85)
at com.google.common.util.concurrent.Futures$6.run(Futures.java:1310)
at
com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:457)
at
com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)
at
com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)
at
com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:202)
at
org.apache.cassandra.streaming.StreamResultFuture.maybeComplete(StreamResultFuture.java:215)
at
org.apache.cassandra.streaming.StreamResultFuture.handleSessionComplete(StreamResultFuture.java:191)
at
org.apache.cassandra.streaming.StreamSession.closeSession(StreamSession.java:429)
at
org.apache.cassandra.streaming.StreamSession.onError(StreamSession.java:527)
at
org.apache.cassandra.streaming.StreamSession.start(StreamSession.java:246)
at
org.apache.cassandra.streaming.StreamCoordinator$StreamSessionConnector.run(StreamCoordinator.java:263)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
dtest: DEBUG: Waiting for decommission to complete
dtest: DEBUG: Status as reported by node 127.0.0.2
dtest: DEBUG: Datacenter: datacenter1
========================
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
UL 127.0.0.1 174.2 KiB 32 78.4%
b8c55c71-bf3d-462b-8c17-3c88d7ac2284 rack1
UN 127.0.0.2 370.04 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1
UN 127.0.0.3 116.7 KiB 32 55.7%
3a4529a3-dc7f-445c-aec3-94417c920fdf rack1
dtest: DEBUG: Sleeping for 30 seconds to allow gossip updates
dtest: DEBUG: Status as reported by node 127.0.0.2
dtest: DEBUG: Datacenter: datacenter1
========================
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
UL 127.0.0.1 174.2 KiB 32 78.4%
b8c55c71-bf3d-462b-8c17-3c88d7ac2284 rack1
UN 127.0.0.2 370.04 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1
UN 127.0.0.3 116.7 KiB 32 55.7%
3a4529a3-dc7f-445c-aec3-94417c920fdf rack1
dtest: DEBUG: removing ccm cluster test at: d:\temp\dtest-ce_wos
dtest: DEBUG: clearing ssl stores from [d:\temp\dtest-ce_wos] directory
--------------------- >> end captured logging << ---------------------
Stacktrace
File "C:\tools\python2\lib\unittest\case.py", line 358, in run
self.tearDown()
File "D:\jenkins\workspace\trunk_dtest_win32\cassandra-dtest\dtest.py", line
667, in tearDown
raise AssertionError('Unexpected error in log, see stdout')
"Unexpected error in log, see stdout\n-------------------- >> begin captured
logging << --------------------\ndtest: DEBUG: cluster ccm directory:
d:\\temp\\dtest-ce_wos\ndtest: DEBUG: Custom init_config not found. Setting
defaults.\ndtest: DEBUG: Done setting configuration options:\n{
'initial_token': None,\n 'num_tokens': '32',\n 'phi_convict_threshold':
5,\n 'range_request_timeout_in_ms': 10000,\n
'read_request_timeout_in_ms': 10000,\n 'request_timeout_in_ms': 10000,\n
'truncate_request_timeout_in_ms': 10000,\n 'write_request_timeout_in_ms':
10000}\ndtest: DEBUG: Status as reported by node 127.0.0.2\ndtest: DEBUG:
Datacenter: datacenter1\n========================\nStatus=Up/Down\n|/
State=Normal/Leaving/Joining/Moving\n-- Address Load Tokens
Owns (effective) Host ID Rack\nUN 127.0.0.1
98.73 KiB 32 78.4% b8c55c71-bf3d-462b-8c17-3c88d7ac2284
rack1\nUN 127.0.0.2 162.38 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1\nUN 127.0.0.3 98.71 KiB 32
55.7% 3a4529a3-dc7f-445c-aec3-94417c920fdf rack1\n\n\ndtest:
DEBUG: Restarting node2\ndtest: DEBUG: Status as reported by node
127.0.0.2\ndtest: DEBUG: Datacenter:
datacenter1\n========================\nStatus=Up/Down\n|/
State=Normal/Leaving/Joining/Moving\n-- Address Load Tokens
Owns (effective) Host ID Rack\nUL 127.0.0.1
98.73 KiB 32 78.4% b8c55c71-bf3d-462b-8c17-3c88d7ac2284
rack1\nUN 127.0.0.2 222.26 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1\nUN 127.0.0.3 98.71 KiB 32
55.7% 3a4529a3-dc7f-445c-aec3-94417c920fdf rack1\n\n\ndtest:
DEBUG: Restarting node2\ndtest: DEBUG: Status as reported by node
127.0.0.2\ndtest: DEBUG: Datacenter:
datacenter1\n========================\nStatus=Up/Down\n|/
State=Normal/Leaving/Joining/Moving\n-- Address Load Tokens
Owns (effective) Host ID Rack\nUL 127.0.0.1
174.2 KiB 32 78.4% b8c55c71-bf3d-462b-8c17-3c88d7ac2284
rack1\nUN 127.0.0.2 336.69 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1\nUN 127.0.0.3 116.7 KiB 32
55.7% 3a4529a3-dc7f-445c-aec3-94417c920fdf rack1\n\n\ndtest:
DEBUG: Restarting node2\ndtest: DEBUG: Status as reported by node
127.0.0.2\ndtest: DEBUG: Datacenter:
datacenter1\n========================\nStatus=Up/Down\n|/
State=Normal/Leaving/Joining/Moving\n-- Address Load Tokens
Owns (effective) Host ID Rack\nUL 127.0.0.1
174.2 KiB 32 78.4% b8c55c71-bf3d-462b-8c17-3c88d7ac2284
rack1\nUN 127.0.0.2 360.82 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1\nUN 127.0.0.3 116.7 KiB 32
55.7% 3a4529a3-dc7f-445c-aec3-94417c920fdf rack1\n\n\ndtest:
DEBUG: Restarting node2\ndtest: DEBUG: Status as reported by node
127.0.0.2\ndtest: DEBUG: Datacenter:
datacenter1\n========================\nStatus=Up/Down\n|/
State=Normal/Leaving/Joining/Moving\n-- Address Load Tokens
Owns (effective) Host ID Rack\nUL 127.0.0.1
174.2 KiB 32 78.4% b8c55c71-bf3d-462b-8c17-3c88d7ac2284
rack1\nUN 127.0.0.2 240.54 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1\nUN 127.0.0.3 116.7 KiB 32
55.7% 3a4529a3-dc7f-445c-aec3-94417c920fdf rack1\n\n\ndtest:
DEBUG: Restarting node2\ndtest: DEBUG: Decommission failed with exception:
Nodetool command
'D:\\jenkins\\workspace\\trunk_dtest_win32\\cassandra\\bin\\nodetool.bat -h
localhost -p 7100 decommission' failed; exit status: 2; stderr: error: Stream
failed\n-- StackTrace --\norg.apache.cassandra.streaming.StreamException:
Stream failed\n\tat
org.apache.cassandra.streaming.management.StreamEventJMXNotifier.onFailure(StreamEventJMXNotifier.java:85)\n\tat
com.google.common.util.concurrent.Futures$6.run(Futures.java:1310)\n\tat
com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:457)\n\tat
com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)\n\tat
com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)\n\tat
com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:202)\n\tat
org.apache.cassandra.streaming.StreamResultFuture.maybeComplete(StreamResultFuture.java:215)\n\tat
org.apache.cassandra.streaming.StreamResultFuture.handleSessionComplete(StreamResultFuture.java:191)\n\tat
org.apache.cassandra.streaming.StreamSession.closeSession(StreamSession.java:429)\n\tat
org.apache.cassandra.streaming.StreamSession.onError(StreamSession.java:527)\n\tat
org.apache.cassandra.streaming.StreamSession.start(StreamSession.java:246)\n\tat
org.apache.cassandra.streaming.StreamCoordinator$StreamSessionConnector.run(StreamCoordinator.java:263)\n\tat
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)\n\tat
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)\n\tat
java.lang.Thread.run(Thread.java:745)\n\n\ndtest: DEBUG: Waiting for
decommission to complete\ndtest: DEBUG: Status as reported by node
127.0.0.2\ndtest: DEBUG: Datacenter:
datacenter1\n========================\nStatus=Up/Down\n|/
State=Normal/Leaving/Joining/Moving\n-- Address Load Tokens
Owns (effective) Host ID Rack\nUL 127.0.0.1
174.2 KiB 32 78.4% b8c55c71-bf3d-462b-8c17-3c88d7ac2284
rack1\nUN 127.0.0.2 370.04 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1\nUN 127.0.0.3 116.7 KiB 32
55.7% 3a4529a3-dc7f-445c-aec3-94417c920fdf rack1\n\n\ndtest:
DEBUG: Sleeping for 30 seconds to allow gossip updates\ndtest: DEBUG: Status as
reported by node 127.0.0.2\ndtest: DEBUG: Datacenter:
datacenter1\n========================\nStatus=Up/Down\n|/
State=Normal/Leaving/Joining/Moving\n-- Address Load Tokens
Owns (effective) Host ID Rack\nUL 127.0.0.1
174.2 KiB 32 78.4% b8c55c71-bf3d-462b-8c17-3c88d7ac2284
rack1\nUN 127.0.0.2 370.04 KiB 32 65.9%
71aacf1d-8e2f-44cf-b354-f10c71313ec6 rack1\nUN 127.0.0.3 116.7 KiB 32
55.7% 3a4529a3-dc7f-445c-aec3-94417c920fdf rack1\n\n\ndtest:
DEBUG: removing ccm cluster test at: d:\\temp\\dtest-ce_wos\ndtest: DEBUG:
clearing ssl stores from [d:\\temp\\dtest-ce_wos]
directory\n--------------------- >> end captured logging <<
---------------------"
Standard Output
Unexpected error in node1 log, error:
ERROR [StreamConnectionEstablisher:1] 2016-04-04 21:20:13,361
StreamSession.java:519 - [Stream #df460340-faaa-11e5-a489-9fa05b8758d9]
Streaming error occurred on session with peer 127.0.0.2
java.net.ConnectException: Connection refused: connect
at sun.nio.ch.Net.connect0(Native Method) ~[na:1.8.0_51]
at sun.nio.ch.Net.connect(Net.java:458) ~[na:1.8.0_51]
at sun.nio.ch.Net.connect(Net.java:450) ~[na:1.8.0_51]
at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:648)
~[na:1.8.0_51]
at
org.apache.cassandra.net.OutboundTcpConnectionPool.newSocket(OutboundTcpConnectionPool.java:141)
~[main/:na]
at
org.apache.cassandra.streaming.DefaultConnectionFactory.createConnection(DefaultConnectionFactory.java:52)
~[main/:na]
at
org.apache.cassandra.streaming.StreamSession.createConnection(StreamSession.java:253)
~[main/:na]
at
org.apache.cassandra.streaming.ConnectionHandler.initiate(ConnectionHandler.java:83)
~[main/:na]
at
org.apache.cassandra.streaming.StreamSession.start(StreamSession.java:240)
~[main/:na]
at
org.apache.cassandra.streaming.StreamCoordinator$StreamSessionConnector.run(StreamCoordinator.java:263)
[main/:na]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[na:1.8.0_51]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_51]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_51]
Standard Error
Started: node1 with pid: 7740
Started: node3 with pid: 7796
Started: node2 with pid: 128
Started: node2 with pid: 4088
Started: node2 with pid: 6116
Started: node2 with pid: 5168
Started: node2 with pid: 1908
Started: node2 with pid: 4436
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
