I am seeing very strange things when trying to decommission a node in my
cluster (detailed logs attached). Here is a nodetool ring report *after*
decommissioning of node 192.168.4.19 (as seen by any other, properly
functioning node).
192.168.4.15 Up Normal 49.9 GB 25.00%
42535295865117307932921825928971026431
192.168.4.20 Up Normal 42.56 GB 8.33%
56713727820156410577229101238628035242
192.168.4.16 Up Normal 29.17 GB 16.67%
85070591730234615865843651857942052863
192.168.4.19 Down Leaving 54.11 GB 16.67%
113427455640312821154458202477256070484
192.168.4.17 Down Normal 48.88 GB 8.33%
127605887595351923798765477786913079295
192.168.4.18 Up Normal 59.44 GB 25.00%
170141183460469231731687303715884105726
192.168.4.12 Up Normal 52.3 GB 0.00%
170141183460469231731687303715884105727
What I am seeing is that after nodetool decommission completes on
192.168.4.19, the next node in the ring (192.168.4.17) 'dies' (see attached
log, its nodetool ring report is quite different). By 'dies' I mean that it
stops communicating with other nodes (but the Cassandra process is still
running and, among other things, compaction continues). After restarting
Cassandra on 192.168.4.17, the ring state gets stuck and the decommissioned
node (192.168.4.19) does not get removed (at least from the nodetool ring
report):
192.168.4.15 Up Normal 49.9 GB 25.00%
42535295865117307932921825928971026431
192.168.4.20 Up Normal 42.56 GB 8.33%
56713727820156410577229101238628035242
192.168.4.16 Up Normal 29.17 GB 16.67%
85070591730234615865843651857942052863
192.168.4.19 Down Leaving 54.11 GB 16.67%
113427455640312821154458202477256070484
192.168.4.17 Up Normal 69.12 GB 8.33%
127605887595351923798765477786913079295
192.168.4.18 Up Normal 58.88 GB 25.00%
170141183460469231731687303715884105726
192.168.4.12 Up Normal 52.3 GB 0.00%
170141183460469231731687303715884105727
Furthermore, when I try running "nodetool removetoken
113427455640312821154458202477256070484", I get:
Exception in thread "main" java.lang.UnsupportedOperationException: Node
/192.168.4.19 is already being removed.
at
org.apache.cassandra.service.StorageService.removeToken(StorageService.java:
1731)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39
)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntr
ospector.java:93)
And when I try running "nodetool removetoken force
113427455640312821154458202477256070484", I get:
RemovalStatus: No token removals in process.
Exception in thread "main" java.lang.NullPointerException
at
org.apache.cassandra.service.StorageService.forceRemoveCompletion(StorageSer
vice.java:1703)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39
)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntr
ospector.java:93)
?!?!?!?
I think have seen this type of behaviour once or twice before (I believe 0.7
b1 or later) but wrote it off as being caused by my misguided tinkering
and/or other Cassandra bugs. This time around, I have done very little with
JMX/CLI/nodetool and I can find no related Cassandra bugs.
Help/suggestions?
Dan Hendry
(403) 660-2297
Reports for the node which is down and should not be (192.168.4.17)
Report of nodetool ring (after decommission complete):
Address Status State Load Owns Token
170141183460469231731687303715884105727
192.168.4.15 Down Normal 49.9 GB 25.00%
42535295865117307932921825928971026431
192.168.4.20 Down Normal 42.56 GB 8.33%
56713727820156410577229101238628035242
192.168.4.16 Down Normal 29.17 GB 16.67%
85070591730234615865843651857942052863
192.168.4.17 Up Normal 69.26 GB 25.00%
127605887595351923798765477786913079295
192.168.4.18 Down Normal 41.07 GB 25.00%
170141183460469231731687303715884105726
192.168.4.12 Down Normal 52.3 GB 0.00%
170141183460469231731687303715884105727
Cassandra system log (all of it for this period):
INFO [CompactionExecutor:1] 2010-12-15 05:22:56,146 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-321-<>
INFO [CompactionExecutor:1] 2010-12-15 05:23:06,111 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-322-<>
INFO [CompactionExecutor:1] 2010-12-15 05:23:10,713 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-323-<>
INFO [CompactionExecutor:1] 2010-12-15 05:23:14,383 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-324-<>
INFO [CompactionExecutor:1] 2010-12-15 05:23:37,485 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-325-<>
INFO [CompactionExecutor:1] 2010-12-15 05:23:40,838 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-326-<>
INFO [ScheduledTasks:1] 2010-12-15 05:23:58,633 Gossiper.java (line 195)
InetAddress /192.168.4.18 is now dead.
INFO [CompactionExecutor:1] 2010-12-15 05:24:09,223 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-300-<>
INFO [GossipStage:1] 2010-12-15 05:24:14,858 Gossiper.java (line 569)
InetAddress /192.168.4.18 is now UP
INFO [HintedHandoff:1] 2010-12-15 05:24:14,858 HintedHandOffManager.java (line
190) Started hinted handoff for endpoint /192.168.4.18
INFO [CompactionExecutor:1] 2010-12-15 05:24:37,878 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-301-<>
INFO [HintedHandoff:1] 2010-12-15 05:25:47,375 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for HintsColumnFamily at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410887152.log',
position=43632816)
INFO [HintedHandoff:1] 2010-12-15 05:25:47,376 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-hintscolumnfam...@130897541(151638 bytes, 2762
operations)
INFO [FlushWriter:1] 2010-12-15 05:25:47,377 Memtable.java (line 155) Writing
memtable-hintscolumnfam...@130897541(151638 bytes, 2762 operations)
INFO [FlushWriter:1] 2010-12-15 05:25:47,802 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/system/HintsColumnFamily-e-565-Data.db (82905 bytes)
INFO [CompactionExecutor:1] 2010-12-15 05:26:04,621 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-302-<>
INFO [CompactionExecutor:1] 2010-12-15 05:27:33,607 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-303-<>
INFO [CompactionExecutor:1] 2010-12-15 05:27:36,342 SSTableReader.java (line
170) Sampling index for
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-304-<>
INFO [CompactionExecutor:1] 2010-12-15 05:27:36,359 CompactionManager.java
(line 272) Compacting
[org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily-e-563-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily-e-564-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily-e-565-Data.db')]
INFO [CompactionExecutor:1] 2010-12-15 05:27:36,818 CompactionManager.java
(line 341) Compacted to
/var/lib/cassandra/data/system/HintsColumnFamily-tmp-e-566-Data.db. 2,401,728
to 2,323,774 (~96% of original) bytes for 3 keys. Time: 458ms.
INFO [HintedHandoff:1] 2010-12-15 05:27:36,819 HintedHandOffManager.java (line
246) Finished hinted handoff of 1259 rows to endpoint /192.168.4.18
INFO [ScheduledTasks:1] 2010-12-15 05:28:01,504 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for PacketEventsByEvent at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410887152.log',
position=52438788)
INFO [ScheduledTasks:1] 2010-12-15 05:28:01,505 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-packeteventsbyev...@1405271761(3501969 bytes,
58712 operations)
INFO [FlushWriter:1] 2010-12-15 05:28:01,505 Memtable.java (line 155) Writing
memtable-packeteventsbyev...@1405271761(3501969 bytes, 58712 operations)
INFO [ScheduledTasks:1] 2010-12-15 05:28:01,505 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for PacketEventsByPacket at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410887152.log',
position=52439320)
INFO [ScheduledTasks:1] 2010-12-15 05:28:01,506 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-packeteventsbypac...@377337421(2982630 bytes,
74164 operations)
INFO [ScheduledTasks:1] 2010-12-15 05:28:01,506 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for UserEventsByUser at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410887152.log',
position=52439320)
INFO [ScheduledTasks:1] 2010-12-15 05:28:01,506 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-usereventsbyu...@390825156(25241826 bytes,
348571 operations)
INFO [FlushWriter:1] 2010-12-15 05:28:01,950 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-327-Data.db (5031004
bytes)
INFO [FlushWriter:1] 2010-12-15 05:28:01,951 Memtable.java (line 155) Writing
memtable-packeteventsbypac...@377337421(2982630 bytes, 74164 operations)
INFO [ScheduledTasks:1] 2010-12-15 05:28:01,975 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for PacketData at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410887152.log',
position=52446120)
INFO [ScheduledTasks:1] 2010-12-15 05:28:01,975 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-packetd...@1320870157(1606520 bytes, 42437
operations)
INFO [FlushWriter:1] 2010-12-15 05:28:03,367 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-316-Data.db (8638111
bytes)
INFO [FlushWriter:1] 2010-12-15 05:28:03,368 Memtable.java (line 155) Writing
memtable-usereventsbyu...@390825156(25241826 bytes, 348571 operations)
INFO [ScheduledTasks:1] 2010-12-15 05:28:03,370 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for UserData at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410887152.log',
position=52452971)
INFO [ScheduledTasks:1] 2010-12-15 05:28:03,370 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-userd...@1914424159(12805859 bytes, 332042
operations)
INFO [FlushWriter:1] 2010-12-15 05:28:29,732 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/kikmetrics/UserEventsByUser-e-326-Data.db (47270642
bytes)
INFO [FlushWriter:1] 2010-12-15 05:28:29,733 Memtable.java (line 155) Writing
memtable-packetd...@1320870157(1606520 bytes, 42437 operations)
INFO [ScheduledTasks:1] 2010-12-15 05:28:29,735 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for UserEventsByEvent at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410887152.log',
position=52459671)
INFO [ScheduledTasks:1] 2010-12-15 05:28:29,735 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-usereventsbyev...@1909852631(39316242 bytes,
461361 operations)
INFO [FlushWriter:1] 2010-12-15 05:28:30,423 Memtable.java (line 162)
Completed flushing /var/lib/cassandra/data/kikmetrics/PacketData-e-304-Data.db
(6087745 bytes)
INFO [FlushWriter:1] 2010-12-15 05:28:30,424 Memtable.java (line 155) Writing
memtable-userd...@1914424159(12805859 bytes, 332042 operations)
INFO [ScheduledTasks:1] 2010-12-15 05:28:30,427 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for ReportDataTimeSeries at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410887152.log',
position=52468503)
INFO [ScheduledTasks:1] 2010-12-15 05:28:30,427 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-reportdatatimeser...@1905776089(297 bytes, 5
operations)
INFO [FlushWriter:1] 2010-12-15 05:28:32,707 Memtable.java (line 162)
Completed flushing /var/lib/cassandra/data/kikmetrics/UserData-e-311-Data.db
(25297490 bytes)
INFO [FlushWriter:1] 2010-12-15 05:28:32,708 Memtable.java (line 155) Writing
memtable-usereventsbyev...@1909852631(39316242 bytes, 461361 operations)
INFO [ScheduledTasks:1] 2010-12-15 05:28:32,710 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for ProcessingBuckets at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410887152.log',
position=52478359)
INFO [ScheduledTasks:1] 2010-12-15 05:28:32,710 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-processingbuck...@851319945(346322 bytes, 8054
operations)
INFO [FlushWriter:1] 2010-12-15 05:28:34,492 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-302-Data.db (50074969
bytes)
INFO [FlushWriter:1] 2010-12-15 05:28:34,492 Memtable.java (line 155) Writing
memtable-reportdatatimeser...@1905776089(297 bytes, 5 operations)
WARN [ScheduledTasks:1] 2010-12-15 05:28:34,493 MessagingService.java (line
527) Dropped 600 MUTATION messages in the last 5000ms
...
... GCInspector stuff
...
INFO [FlushWriter:1] 2010-12-15 05:28:35,102 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/kikmetrics/ReportDataTimeSeries-e-298-Data.db (1044
bytes)
INFO [FlushWriter:1] 2010-12-15 05:28:35,102 Memtable.java (line 155) Writing
memtable-processingbuck...@851319945(346322 bytes, 8054 operations)
INFO [FlushWriter:1] 2010-12-15 05:28:35,462 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/kikmetrics/ProcessingBuckets-e-308-Data.db (165240
bytes)
INFO [COMMIT-LOG-WRITER] 2010-12-15 05:28:35,463 CommitLog.java (line 469)
Discarding obsolete commit
log:CommitLogSegment(/var/lib/cassandra/commitlog/CommitLog-1292408354381.log)
INFO [COMMIT-LOG-WRITER] 2010-12-15 05:28:35,479 CommitLog.java (line 469)
Discarding obsolete commit
log:CommitLogSegment(/var/lib/cassandra/commitlog/CommitLog-1292409626060.log)
WARN [ScheduledTasks:1] 2010-12-15 05:28:39,547 MessagingService.java (line
527) Dropped 3032 MUTATION messages in the last 5000ms
...
... GCInspector stuff
...
... Lots of:
... CompactionManager.java (line 272) Compacting ...
... SSTableReader.java (line 170) Sampling index for ...
...
INFO [Thread-762] 2010-12-15 05:34:00,456 StreamInSession.java (line 160)
Finished streaming session 407160823218155 from /192.168.4.19
INFO [CompactionExecutor:1] 2010-12-15 05:34:00,459 CompactionManager.java
(line 272) Compacting
[org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/PacketData-e-311-Data.db'),org.apache.cassandra.io.s
stable.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-312-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-314-Data.db'),org.apache.cassand
ra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-321-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-322-Data.db'),org.apache
.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-326-Data.db')]
INFO [ScheduledTasks:1] 2010-12-15 05:34:14,157 GCInspector.java (line 133) GC
for ParNew: 214 ms, 45508280 reclaimed leaving 8704984168 used; max is
12783583232
INFO [CompactionExecutor:1] 2010-12-15 05:34:14,235 CompactionIterator.java
(line 134) Compacting large row 313040313239323230393230 (89505798 bytes)
incrementally
INFO [GossipStage:1] 2010-12-15 05:34:17,161 HintedHandOffManager.java (line
151) Deleting any stored hints for /192.168.4.19
INFO [GossipStage:1] 2010-12-15 05:34:17,166 ColumnFamilyStore.java (line 639)
switching in a fresh Memtable for HintsColumnFamily at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292412527693.log',
position=32053331)
INFO [GossipStage:1] 2010-12-15 05:34:17,166 ColumnFamilyStore.java (line 943)
Enqueuing flush of memtable-hintscolumnfam...@1636576102(0 bytes, 0 operations)
INFO [FlushWriter:1] 2010-12-15 05:34:17,166 Memtable.java (line 155) Writing
memtable-hintscolumnfam...@1636576102(0 bytes, 0 operations)
INFO [FlushWriter:1] 2010-12-15 05:34:17,466 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/system/HintsColumnFamily-e-567-Data.db (123 bytes)
INFO [ScheduledTasks:1] 2010-12-15 05:34:21,163 GCInspector.java (line 133) GC
for ParNew: 370 ms, 60388608 reclaimed leaving 8899053688 used; max is
12783583232
INFO [ScheduledTasks:1] 2010-12-15 05:34:28,168 Gossiper.java (line 195)
InetAddress /192.168.4.16 is now dead.
INFO [ScheduledTasks:1] 2010-12-15 05:34:28,168 Gossiper.java (line 195)
InetAddress /192.168.4.18 is now dead.
INFO [ScheduledTasks:1] 2010-12-15 05:34:29,169 Gossiper.java (line 195)
InetAddress /192.168.4.15 is now dead.
INFO [ScheduledTasks:1] 2010-12-15 05:34:30,170 Gossiper.java (line 195)
InetAddress /192.168.4.20 is now dead.
INFO [ScheduledTasks:1] 2010-12-15 05:34:31,182 Gossiper.java (line 195)
InetAddress /192.168.4.12 is now dead.
INFO [CompactionExecutor:1] 2010-12-15 05:34:42,806 CompactionIterator.java
(line 134) Compacting large row 313040313239323230353630 (86666120 bytes)
incrementally
INFO [ScheduledTasks:1] 2010-12-15 05:35:04,286 GCInspector.java (line 133) GC
for ParNew: 331 ms, 44046424 reclaimed leaving 9138906032 used; max is
12783583232
INFO [ScheduledTasks:1] 2010-12-15 05:35:58,874 GCInspector.java (line 133) GC
for ConcurrentMarkSweep: 12482 ms, 6770954320 reclaimed leaving 2622681344
used; max is 12783583232
...
... GC and compacting messages, nothing else specialThis node (192.168.4.19) is the one being decommissioned
Report of nodetool ring (after decommission):
Address Status State Load Owns Token
170141183460469231731687303715884105727
192.168.4.15 Up Normal 49.9 GB 25.00%
42535295865117307932921825928971026431
192.168.4.20 Up Normal 42.56 GB 8.33%
56713727820156410577229101238628035242
192.168.4.16 Up Normal 29.17 GB 16.67%
85070591730234615865843651857942052863
192.168.4.17 Up Normal 48.88 GB 25.00%
127605887595351923798765477786913079295
192.168.4.18 Up Normal 41.07 GB 25.00%
170141183460469231731687303715884105726
192.168.4.12 Up Normal 52.3 GB 0.00%
170141183460469231731687303715884105727
Cassandra system log:
... gc loging ...
INFO [StreamStage:1] 2010-12-15 05:22:52,386 StreamOut.java (line 171) Stream
context metadata
[/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-565-Data.db/(549746128,967141286)
progress=0/417395158 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-667-Data.db/(444306481,846707495)
progress=0/402401014 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-668-Data.db/(0,107867307)
progress=0/107867307 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-669-Data.db/(33530095,69628269)
progress=0/36098174 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-653-Data.db/(249698102,426822654)
progress=0/177124552 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-632-Data.db/(766735902,1349842818)
progress=0/583106916 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByEvent-e-601-Data.db/(491623259,827505860)
progress=0/335882601 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-573-Data.db/(977355716,1596860291)
progress=0/619504575 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-627-Data.db/(137757107,229216170)
progress=0/91459063 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-435-Data.db/(2666389955,4283847780)
progress=0/1617457825 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-567-Data.db/(2260742911,3765852546)
progress=0/1505109635 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-642-Data.db/(51212947,102787386)
progress=0/51574439 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-212-Data.db/(2975085688,3452779516)
progress=0/477693828 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-640-Data.db/(28206959,56318703)
progress=0/28111744 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-632-Data.db/(145312088,242167061)
progress=0/96854973 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-639-Data.db/(30472627,61160417)
progress=0/30687790 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-614-Data.db/(311747980,518490903)
progress=0/206742923 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-643-Data.db/(36580,74400)
progress=0/37820 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-638-Data.db/(144388535,267313016)
progress=0/122924481 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-290-Data.db/(6032518487,6965275684)
progress=0/932757197 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-634-Data.db/(19201545,31928478)
progress=0/12726933 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-624-Data.db/(70844058,118007411)
progress=0/47163353 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-641-Data.db/(19483822,39084165)
progress=0/19600343 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketEventsByPacket-e-609-Data.db/(646916559,1078064181)
progress=0/431147622 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByUser-e-644-Data.db/(13025781,248370504)
progress=0/235344723 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByUser-e-632-Data.db/(29531988,69582135)
progress=0/40050147 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByUser-e-559-Data.db/(3189228662,4703089652)
progress=0/1513860990 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByUser-e-465-Data.db/(1885350835,2858632852)
progress=0/973282017 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByUser-e-643-Data.db/(144915081,1146172922)
progress=0/1001257841 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByUser-e-645-Data.db/(152357,292364)
progress=0/140007 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByUser-e-639-Data.db/(2184232010,3723017720)
progress=0/1538785710 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByUser-e-634-Data.db/(28065487,56018284)
progress=0/27952797 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByUser-e-633-Data.db/(28919927,58090897)
progress=0/29170970 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketData-e-634-Data.db/(31634394,63247835)
progress=0/31613441 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketData-e-622-Data.db/(100932666,168097689)
progress=0/67165023 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketData-e-628-Data.db/(92147487,160155211)
progress=0/68007724 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketData-e-635-Data.db/(24341,49228)
progress=0/24887 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketData-e-607-Data.db/(52771692,87930059)
progress=0/35158367 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketData-e-633-Data.db/(14092369,28260732)
progress=0/14168363 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketData-e-592-Data.db/(1370564921,2283773798)
progress=0/913208877 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketData-e-617-Data.db/(441257881,735206456)
progress=0/293948575 - 0%,
/var/lib/cassandra/data/kikmetrics/PacketData-e-632-Data.db/(99356093,193031999)
progress=0/93675906 - 0%,
/var/lib/cassandra/data/kikmetrics/UserData-e-630-Data.db/(21289570,42369278)
progress=0/21079708 - 0%,
/var/lib/cassandra/data/kikmetrics/UserData-e-568-Data.db/(78662850,131364582)
progress=0/52701732 - 0%,
/var/lib/cassandra/data/kikmetrics/UserData-e-463-Data.db/(86898888,144898152)
progress=0/57999264 - 0%,
/var/lib/cassandra/data/kikmetrics/UserData-e-628-Data.db/(65186692,109442848)
progress=0/44256156 - 0%,
/var/lib/cassandra/data/kikmetrics/UserData-e-631-Data.db/(99708,196041)
progress=0/96333 - 0%,
/var/lib/cassandra/data/kikmetrics/UserData-e-629-Data.db/(14109767,28276054)
progress=0/14166287 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-492-Data.db/(2431222057,3585750681)
progress=0/1154528624 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-297-Data.db/(1420569477,1980073414)
progress=0/559503937 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-633-Data.db/(257676,262423)
progress=0/4747 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-632-Data.db/(65005566,148900534)
progress=0/83894968 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-631-Data.db/(291969,112310182)
progress=0/112018213 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-564-Data.db/(962006002,1611531851)
progress=0/649525849 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-626-Data.db/(739769696,940532643)
progress=0/200762947 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-630-Data.db/(61764071,101407443)
progress=0/39643372 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-628-Data.db/(655,67470409)
progress=0/67469754 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-556-Data.db/(402893617,538868441)
progress=0/135974824 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-590-Data.db/(597607933,924204037)
progress=0/326596104 - 0%,
/var/lib/cassandra/data/kikmetrics/UserEventsByEvent-e-619-Data.db/(283906738,424113395)
progress=0/140206657 - 0%,
/var/lib/cassandra/data/kikmetrics/ReportDataTimeSeries-e-560-Data.db/(5570738,5682817)
progress=0/112079 - 0%,
/var/lib/cassandra/data/kikmetrics/ReportDataTimeSeries-e-561-Data.db/(3096,5476)
progress=0/2380 - 0%,
/var/lib/cassandra/data/kikmetrics/ProcessingBuckets-e-615-Data.db/(348,694)
progress=0/346 - 0%,
/var/lib/cassandra/data/kikmetrics/ProcessingBuckets-e-610-Data.db/(15194457,37079675)
progress=0/21885218 - 0%,
/var/lib/cassandra/data/kikmetrics/ProcessingBuckets-e-612-Data.db/(11508273,33170366)
progress=0/21662093 - 0%,
/var/lib/cassandra/data/kikmetrics/ProcessingBuckets-e-611-Data.db/(29745,71449)
progress=0/41704 - 0%,
/var/lib/cassandra/data/kikmetrics/ProcessingBuckets-e-613-Data.db/(11696292,33853206)
progress=0/22156914 - 0%], 67 sstables.
INFO [StreamStage:1] 2010-12-15 05:22:52,387 StreamOutSession.java (line 175)
Streaming to /192.168.4.18
INFO [ScheduledTasks:1] 2010-12-15 05:22:58,384 GCInspector.java (line 133) GC
for ParNew: 202 ms, 24589768 reclaimed leaving 9378250752 used; max is
12783583232
INFO [CompactionExecutor:1] 2010-12-15 05:23:00,715 CompactionManager.java
(line 341) Compacted to
/var/lib/cassandra/data/kikmetrics/ProcessingBuckets-tmp-e-614-Data.db.
104,174,696 to 37,568,355 (~36% of original) bytes for 10 keys. Time: 11,460ms.
INFO [ScheduledTasks:1] 2010-12-15 05:24:01,416 Gossiper.java (line 195)
InetAddress /192.168.4.18 is now dead.
INFO [GossipStage:1] 2010-12-15 05:24:15,428 Gossiper.java (line 569)
InetAddress /192.168.4.18 is now UP
INFO [HintedHandoff:1] 2010-12-15 05:24:15,428 HintedHandOffManager.java (line
190) Started hinted handoff for endpoint /192.168.4.18
INFO [HintedHandoff:1] 2010-12-15 05:24:16,153 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for HintsColumnFamily at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410801462.log',
position=91175710)
INFO [HintedHandoff:1] 2010-12-15 05:24:16,153 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-hintscolumnfam...@230222401(3188 bytes, 61
operations)
INFO [FlushWriter:1] 2010-12-15 05:24:16,153 Memtable.java (line 155) Writing
memtable-hintscolumnfam...@230222401(3188 bytes, 61 operations)
INFO [CompactionExecutor:1] 2010-12-15 05:24:16,153 CompactionManager.java
(line 272) Compacting
[org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily-e-1170-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily-e-1169-Data.db')]
INFO [FlushWriter:1] 2010-12-15 05:24:16,325 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/system/HintsColumnFamily-e-1171-Data.db (2418 bytes)
INFO [CompactionExecutor:1] 2010-12-15 05:24:16,347 CompactionManager.java
(line 341) Compacted to
/var/lib/cassandra/data/system/HintsColumnFamily-tmp-e-1172-Data.db. 625 to
446 (~71% of original) bytes for 2 keys. Time: 192ms.
INFO [HintedHandoff:1] 2010-12-15 05:24:16,348 HintedHandOffManager.java (line
246) Finished hinted handoff of 34 rows to endpoint /192.168.4.18
INFO [ScheduledTasks:1] 2010-12-15 05:28:14,590 Gossiper.java (line 195)
InetAddress /192.168.4.17 is now dead.
INFO [HintedHandoff:1] 2010-12-15 05:28:34,601 HintedHandOffManager.java (line
190) Started hinted handoff for endpoint /192.168.4.17
INFO [GossipStage:1] 2010-12-15 05:28:34,601 Gossiper.java (line 569)
InetAddress /192.168.4.17 is now UP
INFO [HintedHandoff:1] 2010-12-15 05:28:35,710 ColumnFamilyStore.java (line
639) switching in a fresh Memtable for HintsColumnFamily at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292410801462.log',
position=105316309)
INFO [HintedHandoff:1] 2010-12-15 05:28:35,711 ColumnFamilyStore.java (line
943) Enqueuing flush of memtable-hintscolumnfam...@899272834(6704 bytes, 125
operations)
INFO [FlushWriter:1] 2010-12-15 05:28:35,711 Memtable.java (line 155) Writing
memtable-hintscolumnfam...@899272834(6704 bytes, 125 operations)
INFO [CompactionExecutor:1] 2010-12-15 05:28:35,711 CompactionManager.java
(line 272) Compacting
[org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily-e-1172-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily-e-1171-Data.db')]
INFO [FlushWriter:1] 2010-12-15 05:28:35,807 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/system/HintsColumnFamily-e-1173-Data.db (4724 bytes)
INFO [CompactionExecutor:1] 2010-12-15 05:28:35,826 CompactionManager.java
(line 341) Compacted to
/var/lib/cassandra/data/system/HintsColumnFamily-tmp-e-1174-Data.db. 2,864 to
446 (~15% of original) bytes for 2 keys. Time: 114ms.
INFO [HintedHandoff:1] 2010-12-15 05:28:35,827 HintedHandOffManager.java (line
246) Finished hinted handoff of 69 rows to endpoint /192.168.4.17
INFO [RMI TCP Connection(18)-199.102.46.226] 2010-12-15 05:34:18,381
MessagingService.java (line 366) Shutting down MessageService...
INFO [RMI TCP Connection(18)-199.102.46.226] 2010-12-15 05:34:18,383
MessagingService.java (line 383) Shutdown complete (no further commands will be
processed)
INFO [ACCEPT-/192.168.4.19] 2010-12-15 05:34:18,383 MessagingService.java
(line 559) MessagingService shutting down server thread.
INFO [RMI TCP Connection(18)-199.102.46.226] 2010-12-15 05:34:18,385
StorageService.java (line 455) Decommissioned
ERROR [Thread-29] 2010-12-15 05:34:19,911 AbstractCassandraDaemon.java (line
90) Fatal exception in thread Thread[Thread-29,5,main]
java.util.concurrent.RejectedExecutionException: ThreadPoolExecutor has shut
down
at
org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor$1.rejectedExecution(DebuggableThreadPoolExecutor.java:62)
at
java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
at
java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
at
org.apache.cassandra.net.MessagingService.receive(MessagingService.java:393)
at
org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:84)
ERROR [Thread-16] 2010-12-15 05:34:21,443 AbstractCassandraDaemon.java (line
90) Fatal exception in thread Thread[Thread-16,5,main]
java.util.concurrent.RejectedExecutionException: ThreadPoolExecutor has shut
down
at
org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor$1.rejectedExecution(DebuggableThreadPoolExecutor.java:62)
at
java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
at
java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
at
org.apache.cassandra.net.MessagingService.receive(MessagingService.java:393)
at
org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:84)
ERROR [Thread-35] 2010-12-15 05:34:23,248 AbstractCassandraDaemon.java (line
90) Fatal exception in thread Thread[Thread-35,5,main]
java.util.concurrent.RejectedExecutionException: ThreadPoolExecutor has shut
down
at
org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor$1.rejectedExecution(DebuggableThreadPoolExecutor.java:62)
at
java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
at
java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
at
org.apache.cassandra.net.MessagingService.receive(MessagingService.java:393)
at
org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:84)
ERROR [Thread-18] 2010-12-15 05:34:23,897 AbstractCassandraDaemon.java (line
90) Fatal exception in thread Thread[Thread-18,5,main]
java.util.concurrent.RejectedExecutionException: ThreadPoolExecutor has shut
down
at
org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor$1.rejectedExecution(DebuggableThreadPoolExecutor.java:62)
at
java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
at
java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
at
org.apache.cassandra.net.MessagingService.receive(MessagingService.java:393)
at
org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:84)
ERROR [Thread-19] 2010-12-15 05:34:24,168 AbstractCassandraDaemon.java (line
90) Fatal exception in thread Thread[Thread-19,5,main]
java.util.concurrent.RejectedExecutionException: ThreadPoolExecutor has shut
down
at
org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor$1.rejectedExecution(DebuggableThreadPoolExecutor.java:62)
at
java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
at
java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
at
org.apache.cassandra.net.MessagingService.receive(MessagingService.java:393)
at
org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:84)
Reports from some other node in the ring (192.168.4.20)
Report of nodetool ring (after decommission complete):
Address Status State Load Owns Token
170141183460469231731687303715884105727
192.168.4.15 Up Normal 49.9 GB 25.00%
42535295865117307932921825928971026431
192.168.4.20 Up Normal 42.56 GB 8.33%
56713727820156410577229101238628035242
192.168.4.16 Up Normal 29.17 GB 16.67%
85070591730234615865843651857942052863
192.168.4.19 Down Leaving 54.11 GB 16.67%
113427455640312821154458202477256070484
192.168.4.17 Down Normal 48.88 GB 8.33%
127605887595351923798765477786913079295
192.168.4.18 Up Normal 59.44 GB 25.00%
170141183460469231731687303715884105726
192.168.4.12 Up Normal 52.3 GB 0.00%
170141183460469231731687303715884105727
Cassandra system log:
INFO [COMMIT-LOG-WRITER] 2010-12-15 05:22:01,588 CommitLogSegment.java (line
50) Creating new commitlog segment
/var/lib/cassandra/commitlog/CommitLog-1292412121588.log
INFO [ScheduledTasks:1] 2010-12-15 05:24:00,060 Gossiper.java (line 195)
InetAddress /192.168.4.18 is now dead.
INFO [GossipStage:1] 2010-12-15 05:24:15,065 Gossiper.java (line 569)
InetAddress /192.168.4.18 is now UP
INFO [HintedHandoff:1] 2010-12-15 05:24:15,065 HintedHandOffManager.java (line
190) Started hinted handoff for endpoint /192.168.4.18
INFO [HintedHandoff:1] 2010-12-15 05:24:15,066 HintedHandOffManager.java (line
246) Finished hinted handoff of 0 rows to endpoint /192.168.4.18
INFO [ScheduledTasks:1] 2010-12-15 05:28:14,124 Gossiper.java (line 195)
InetAddress /192.168.4.17 is now dead.
INFO [GossipStage:1] 2010-12-15 05:28:34,533 Gossiper.java (line 569)
InetAddress /192.168.4.17 is now UP
INFO [HintedHandoff:1] 2010-12-15 05:28:34,533 HintedHandOffManager.java (line
190) Started hinted handoff for endpoint /192.168.4.17
INFO [HintedHandoff:1] 2010-12-15 05:28:34,534 HintedHandOffManager.java (line
246) Finished hinted handoff of 0 rows to endpoint /192.168.4.17
INFO [GossipStage:1] 2010-12-15 05:34:16,775 HintedHandOffManager.java (line
151) Deleting any stored hints for /192.168.4.19
INFO [GossipStage:1] 2010-12-15 05:34:16,776 ColumnFamilyStore.java (line 639)
switching in a fresh Memtable for HintsColumnFamily at
CommitLogContext(file='/var/lib/cassandra/commitlog/CommitLog-1292412121588.log',
position=70058963)
INFO [GossipStage:1] 2010-12-15 05:34:16,776 ColumnFamilyStore.java (line 943)
Enqueuing flush of memtable-hintscolumnfam...@252108826(0 bytes, 0 operations)
INFO [CompactionExecutor:1] 2010-12-15 05:34:16,777 CompactionManager.java
(line 272) Compacting
[org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily-e-1452-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/system/HintsColumnFamily-e-1451-Data.db')]
INFO [FlushWriter:1] 2010-12-15 05:34:16,777 Memtable.java (line 155) Writing
memtable-hintscolumnfam...@252108826(0 bytes, 0 operations)
INFO [FlushWriter:1] 2010-12-15 05:34:16,850 Memtable.java (line 162)
Completed flushing
/var/lib/cassandra/data/system/HintsColumnFamily-e-1453-Data.db (123 bytes)
INFO [CompactionExecutor:1] 2010-12-15 05:34:16,850 CompactionManager.java
(line 341) Compacted to
/var/lib/cassandra/data/system/HintsColumnFamily-tmp-e-1454-Data.db. 408 to
250 (~61% of original) bytes for 1 keys. Time: 73ms.
INFO [GossipStage:1] 2010-12-15 05:34:16,851 StorageService.java (line 796)
Removing token 113427455640312821154458202477256070484 for /192.168.4.19
INFO [GossipStage:1] 2010-12-15 05:34:49,525 Gossiper.java (line 577) Node
/192.168.4.19 is now part of the cluster
INFO [GossipStage:1] 2010-12-15 05:34:49,528 StorageService.java (line 718)
Node /192.168.4.19 state jump to leaving
INFO [ScheduledTasks:1] 2010-12-15 05:36:00,290 Gossiper.java (line 195)
InetAddress /192.168.4.17 is now dead.
