Re: RC1 - joining cluster

[Joe Obernberger]

Whoops - had it in the wrong datacenter.  Same issue - new node is 
stuck in UJ, but I can start/stop OK with systemctl.

Datacenter: datacenter1
=======================
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
--  Address                    Load        
Tokens  Owns (effective)  Host 
ID                               Rack
UN  helene.querymasters.com    423.92 MiB  30     
18.6%             2529b6ed-cdb2-43c2-bdd7-171cfe308bd3  rack1
UJ  fortuna.querymasters.com   1.75 GiB    200    
?                 49e4f571-7d1c-4e1e-aca7-5bbe076596f7  
rack1
UN  charon.querymasters.com    2.22 GiB    200    
98.5%             d9702f96-256e-45ae-8e12-69a42712be50  rack1
UN  eros.querymasters.com      2.21 GiB    200    
98.5%             93f9cb0f-ea71-4e3d-b62a-f0ea0e888c47  rack1
UN  hercules.querymasters.com  58.65 MiB   4      
2.6%              a1a16910-9167-4174-b34b-eb859d36347e  rack1
UN  chaos.querymasters.com     1.82 GiB    120    
81.8%             08a19658-40be-4e55-8709-812b3d4ac750  rack1

I am able to restart the server (fortuna - after about 3 hours), but I 
then get this:

ERROR [Stream-Deserializer-/172.16.100.253:7000-493728e3] 2021-05-07 
21:17:35,805 StreamingInboundHandler.java:205 - [Stream channel: 
493728e3] stream operation from /172.16.100.253:7000 failed
java.lang.IllegalStateException: unknown stream session: 
27c00760-af9b-11eb-b7ee-5d6a136b5405 - 0
        at 
org.apache.cassandra.streaming.messages.IncomingStreamMessage$1.deserialize(IncomingStreamMessage.java:45)
        at 
org.apache.cassandra.streaming.messages.IncomingStreamMessage$1.deserialize(IncomingStreamMessage.java:38)
        at 
org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:53)
        at 
org.apache.cassandra.streaming.async.StreamingInboundHandler$StreamDeserializingTask.run(StreamingInboundHandler.java:172)
        at 
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:829)
ERROR [Stream-Deserializer-/172.16.100.253:7000-e313e37d] 2021-05-07 
21:17:36,208 StreamSession.java:882 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405] Remote peer /172.16.100.253:7000 
failed stream session.
INFO  [Stream-Deserializer-/172.16.100.253:7000-e313e37d] 2021-05-07 
21:17:36,209 StreamResultFuture.java:192 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405] Session with /172.16.100.253:7000 
is complete
INFO  [Stream-Deserializer-/172.16.100.253:7000-e313e37d] 2021-05-07 
21:17:36,209 StreamSession.java:359 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405] Starting streaming to 
/172.16.100.37:7000
INFO  [Stream-Deserializer-/172.16.100.253:7000-e313e37d] 2021-05-07 
21:17:36,214 StreamCoordinator.java:263 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405, ID#0] Beginning stream session 
with /172.16.100.37:7000
INFO  [Stream-Deserializer-/172.16.100.36:7000-9d343b7e] 2021-05-07 
21:17:37,808 StreamResultFuture.java:178 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405 ID#0] Prepare completed. Receiving 
0 files(0.000KiB), sending 0 files(0.000KiB)
INFO  [Stream-Deserializer-/172.16.100.39:7000-1c5eddba] 2021-05-07 
21:17:37,809 StreamResultFuture.java:178 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405 ID#0] Prepare completed. Receiving 
0 files(0.000KiB), sending 0 files(0.000KiB)
INFO  [Stream-Deserializer-/172.16.100.36:7000-9d343b7e] 2021-05-07 
21:17:38,209 StreamResultFuture.java:192 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405] Session with /172.16.100.36:7000 
is complete
INFO  [Stream-Deserializer-/172.16.100.39:7000-1c5eddba] 2021-05-07 
21:17:38,210 StreamResultFuture.java:192 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405] Session with /172.16.100.39:7000 
is complete
INFO  [Stream-Deserializer-/172.16.100.37:7000-d2676988] 2021-05-07 
21:17:41,416 StreamResultFuture.java:178 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405 ID#0] Prepare completed. Receiving 
0 files(0.000KiB), sending 0 files(0.000KiB)
INFO  [Stream-Deserializer-/172.16.100.37:7000-d2676988] 2021-05-07 
21:17:41,818 StreamResultFuture.java:192 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405] Session with /172.16.100.37:7000 
is complete
WARN  [Stream-Deserializer-/172.16.100.37:7000-d2676988] 2021-05-07 
21:17:41,822 StreamResultFuture.java:219 - [Stream 
#27c00760-af9b-11eb-b7ee-5d6a136b5405] Stream failed
ERROR [main] 2021-05-07 21:17:41,823 StorageService.java:1773 - Error 
while waiting on bootstrap to complete. Bootstrap will have to be restarted.
java.util.concurrent.ExecutionException: 
org.apache.cassandra.streaming.StreamException: Stream failed
        at 
com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:552)
        at 
com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:533)
        at 
org.apache.cassandra.service.StorageService.bootstrap(StorageService.java:1766)
        at 
org.apache.cassandra.service.StorageService.joinTokenRing(StorageService.java:1054)
        at 
org.apache.cassandra.service.StorageService.joinTokenRing(StorageService.java:1015)
        at 
org.apache.cassandra.service.StorageService.initServer(StorageService.java:799)
        at 
org.apache.cassandra.service.StorageService.initServer(StorageService.java:729)
        at 
org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:420)
        at 
org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:763)
        at 
org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:887)
Caused by: org.apache.cassandra.streaming.StreamException: Stream failed
        at 
org.apache.cassandra.streaming.management.StreamEventJMXNotifier.onFailure(StreamEventJMXNotifier.java:88)
        at 
com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1056)
        at 
com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
        at 
com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1138)
        at 
com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:958)
        at 
com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:748)
        at 
org.apache.cassandra.streaming.StreamResultFuture.maybeComplete(StreamResultFuture.java:220)
        at 
org.apache.cassandra.streaming.StreamResultFuture.handleSessionComplete(StreamResultFuture.java:196)
        at 
org.apache.cassandra.streaming.StreamSession.closeSession(StreamSession.java:506)
        at 
org.apache.cassandra.streaming.StreamSession.complete(StreamSession.java:837)
        at 
org.apache.cassandra.streaming.StreamSession.messageReceived(StreamSession.java:596)
        at 
org.apache.cassandra.streaming.async.StreamingInboundHandler$StreamDeserializingTask.run(StreamingInboundHandler.java:189)
        at 
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:829)
WARN  [main] 2021-05-07 21:17:41,843 StorageService.java:1090 - Some 
data streaming failed. Use nodetool to check bootstrap state and resume. 
For more, see `nodetool help bootstrap`. IN_PROGRESS

-Joe

On 5/7/2021 5:37 PM, Joe Obernberger wrote:
When I try to halt the joining node with systemctl stop cassandra, it 
hangs.  I don't see it doing any network, disk, or CPU activity using 
tools like iotop, atop, and top.

I ended up kill -9'ing the process.  I tried the same join on a 
different machine, and the same issue occurs.  It hangs in UJ.  I 
deleted all data on the new node (not much there cuz it's new!), and 
tried again.  Same issue.

In other news, java 11 is working.  :)

-Joe


On 5/7/2021 5:07 PM, Joe Obernberger wrote:
Have an existing 5 node RC1 cluster and trying to join two more nodes 
to it.
The new node is stuck in the UJ status:

Datacenter: datacenter1
=======================
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
--  Address         Load        Tokens  Owns 
(effective)  Host 
ID                               Rack
UN  172.16.100.208  410.12 MiB  30      
18.6%           � 2529b6ed-cdb2-43c2-bdd7-171cfe308bd3  
rack1
UN  172.16.100.36   2.15 GiB    200     
98.5%           � d9702f96-256e-45ae-8e12-69a42712be50  
rack1
UN  172.16.100.39   2.14 GiB    200     
98.5%           � 93f9cb0f-ea71-4e3d-b62a-f0ea0e888c47  
rack1
UN  172.16.100.253  56.97 MiB   4       
2.6%            � 
a1a16910-9167-4174-b34b-eb859d36347e  rack1
UN  172.16.100.37   1.77 GiB    120     
81.8%           � 08a19658-40be-4e55-8709-812b3d4ac750  
rack1

Datacenter: dc1
===============
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
--  Address         Load        Tokens  Owns 
(effective)  Host 
ID                               Rack
UJ  172.16.100.248  1.31 MiB    200     
?               � 
054109ad-3a5e-4680-b4ad-f9c08089238c  rack1

What can I check?

-Joe