Page MenuHomePhabricator

High storage utilization on restbase1014.eqiad.wmnet
Closed, ResolvedPublic

Description

Rack d consists of hosts 1009, 1014, and 1015. Hosts 1009 and 1015 have 2 instances each, and 1014 has 3 instances, giving it a disproportionate amount of the rack d storage, and rendering it critically low on free space at this time.

eevans@restbase1014:~$ df -h /srv
Filesystem                        Size  Used Avail Use% Mounted on
/dev/mapper/restbase1014--vg-srv  4.5T  4.3T  252G  95% /srv
eevans@restbase1014:~$

Another contributing factor is that randomized token placement has left 1014 a bit hotter than most.

Datacenter: eqiad
=================
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
--  Address                     Load       Tokens       Owns (effective)  Host ID                               Rack
UN  restbase1009-b.eqiad.wmnet  1.49 TB    256          14.9%             5312305a-967f-44e4-a801-00742edaa31a  d
UN  restbase1008-b.eqiad.wmnet  1.08 TB    256          11.6%             3e84a456-f7c9-4010-be0b-c14d5c366b43  b
UN  restbase1008-c.eqiad.wmnet  973.65 GB  256          12.2%             ad7a3060-62cd-48f3-b672-41ae9e1e777a  b
UN  restbase1007-a.eqiad.wmnet  919.96 GB  256          10.3%             de8a87d8-0d7a-41e2-aa68-b1343ddd2d12  a
UN  restbase1014-a.eqiad.wmnet  1.39 TB    256          13.1%             2cec3424-3ff1-43b2-bee8-c1e591c5b1b5  d
UN  restbase1007-b.eqiad.wmnet  1.41 TB    256          11.6%             712e0f14-437e-4287-8b12-73a82b92b075  a
UN  restbase1007-c.eqiad.wmnet  1.11 TB    256          11.5%             a8016540-101d-4491-9ee6-99457687a7f0  a
UN  restbase1014-b.eqiad.wmnet  1.56 TB    256          15.9%             4dfe9e65-c781-4e83-9682-d84aa8a352cb  d
UN  restbase1014-c.eqiad.wmnet  1.26 TB    256          14.5%             bcb899a0-fd5a-4d62-a2a8-40aae6de1be8  d
UN  restbase1012-a.eqiad.wmnet  1.12 TB    256          12.1%             1f5ed333-4fef-4c05-8c2c-0612b333ee7e  b
UN  restbase1015-a.eqiad.wmnet  1.39 TB    256          14.1%             044aea98-359f-46da-a5dd-f2a47cc8fa19  d
UN  restbase1012-b.eqiad.wmnet  1.27 TB    256          13.3%             4a6e4347-1124-4246-8de6-ca2171b55e3a  b
UN  restbase1015-b.eqiad.wmnet  1.47 TB    256          14.4%             7a8c2f76-109c-4877-afc6-a1e6ab49e07d  d
UN  restbase1012-c.eqiad.wmnet  1.09 TB    256          13.1%             2169eba7-0c80-4788-b367-4e0e4ca51691  b
UN  restbase1013-a.eqiad.wmnet  1.23 TB    256          12.8%             a6d23e82-d6bd-44b4-b9af-8c19e5d7d959  b
UN  restbase1013-b.eqiad.wmnet  1.28 TB    256          12.8%             6e22a9b6-c26a-4a55-be1b-39d4ab99ddfa  b
UN  restbase1010-a.eqiad.wmnet  996.86 GB  256          11.1%             e3968332-41a2-4648-9aa3-6338c3815ad2  a
UN  restbase1010-b.eqiad.wmnet  1.02 TB    256          9.9%              4bece9fd-cb5f-4d85-8083-8e1b478e4bf7  a
UN  restbase1010-c.eqiad.wmnet  1.24 TB    256          12.3%             8eb06cec-9797-42c0-a5c6-7b9b020d4aeb  a
UN  restbase1011-a.eqiad.wmnet  1014.3 GB  256          11.7%             3692de17-96cd-4fd9-a22d-28fab29954bd  a
UN  restbase1011-b.eqiad.wmnet  1.41 TB    256          11.5%             3bcebbb9-840c-45e0-80c3-02d2679b3c5c  a
UN  restbase1011-c.eqiad.wmnet  887 GB     256          10.0%             8809d40b-ce37-4e5e-a022-daa33352d1b4  a
UN  restbase1009-a.eqiad.wmnet  1.28 TB    256          13.2%             1c327cee-e382-4c93-a183-f06ebead1ca0  d
UN  restbase1008-a.eqiad.wmnet  1.24 TB    256          12.2%             d2717bbf-fdf6-4faf-82e7-a73543ca6ea7  b

Cleanups on the 1014 instances complete in short order (successfully), indicating there is no space to be freed.

Event Timeline

Eevans created this task.Jul 5 2016, 3:10 PM
Restricted Application added subscribers: Zppix, Aklapper. · View Herald TranscriptJul 5 2016, 3:10 PM
Eevans added a comment.Jul 5 2016, 3:23 PM

The short term solution here is to add more rack d instances (to 1009 and 1015), and get 1014 cleaned up. I see two options:

Option #1: Plow through the 2.2.6 upgrade, then bootstrap 1009-c and/or 1015-c, and cleanup 1014-{a,b,c}.

Option #2: Bootstrap 1009-c and/or 1015-c, and cleanup 1014-{a,b,c}.

You are never, ever, ever supposed to perform range movements in a mixed version cluster (at this time 1007-{a,b,c} are running 2.2.6, the rest of the cluster is running 2.1.13). Option #1 keeps us from violating this cardinal rule. However, given the problems we have already experienced with the upgrade, rushing through the remaining nodes is unwise. Additionally, cleaning up 1014 at 95% utilization is already dubious, postponing it further will only make matters worse.

Option #2 might fail. The likely consequences of a failure are that the bootstrap would not succeed, but as with any unsupported operation, YMMV. This still feels the least risky to me, and so if there are no objections, I will start a bootstrap of 1009-c (RSN).

Change 297417 had a related patch set uploaded (by Eevans):
Bootstrap Cassandra instances restbase1009-c

https://gerrit.wikimedia.org/r/297417

Given the urgency of the matter, I'm voting for trying option #2 as well. Waiting the upgrade to be complete does not sound feasible given the current constraints. Even though making range movements in a mixed env just shouldn't be done, I don't see how the cluster could go down for this bootstrap. From what I can tell, the worst-case scenario here is that the two new bootstraps will fail but the cluster will remain intact otherwise.

Change 297417 merged by Filippo Giunchedi:
Bootstrap Cassandra instance restbase1009-c

https://gerrit.wikimedia.org/r/297417

Mentioned in SAL [2016-07-05T16:09:05Z] <urandom> Bootstrapping restbase1009-c.eqiad.wmnet : T139362

Eevans added a comment.Jul 5 2016, 4:30 PM

A bootstrap of restbase1009-c.eqiad.wmnet is running, but there were some errors logged. The IPs in question are for restbase1007-{a,b,c} (the 2.2.6 instances), so not entirely unexpected. With any luck this does not result in ~12 hours of streaming, only to fail for these (early) errors. Stay tuned...

1ERROR [STREAM-OUT-/10.64.0.230] 2016-07-05 16:16:44,871 StreamSession.java:505 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Streaming error occurred
2java.io.IOException: Connection reset by peer
3 at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_91]
4 at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_91]
5 at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_91]
6 at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_91]
7 at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_91]
8 at org.apache.cassandra.io.util.DataOutputStreamAndChannel.write(DataOutputStreamAndChannel.java:48) ~[apache-cassandra-2.1.13.jar:2.1.13]
9 at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:44) ~[apache-cassandra-2.1.13.jar:2.1.13]
10 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:351) [apache-cassandra-2.1.13.jar:2.1.13]
11 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.run(ConnectionHandler.java:323) [apache-cassandra-2.1.13.jar:2.1.13]
12 at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
13ERROR [STREAM-OUT-/10.64.0.231] 2016-07-05 16:16:44,871 StreamSession.java:505 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Streaming error occurred
14java.io.IOException: Connection reset by peer
15 at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_91]
16 at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_91]
17 at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_91]
18 at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_91]
19 at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_91]
20 at org.apache.cassandra.io.util.DataOutputStreamAndChannel.write(DataOutputStreamAndChannel.java:48) ~[apache-cassandra-2.1.13.jar:2.1.13]
21 at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:44) ~[apache-cassandra-2.1.13.jar:2.1.13]
22 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:351) [apache-cassandra-2.1.13.jar:2.1.13]
23 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.run(ConnectionHandler.java:323) [apache-cassandra-2.1.13.jar:2.1.13]
24 at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
25ERROR [STREAM-IN-/10.64.0.231] 2016-07-05 16:16:44,871 StreamSession.java:505 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Streaming error occurred
26java.io.IOException: Connection reset by peer
27 at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[na:1.8.0_91]
28 at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[na:1.8.0_91]
29 at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) ~[na:1.8.0_91]
30 at sun.nio.ch.IOUtil.read(IOUtil.java:197) ~[na:1.8.0_91]
31 at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) ~[na:1.8.0_91]
32 at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:51) ~[apache-cassandra-2.1.13.jar:2.1.13]
33 at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:250) ~[apache-cassandra-2.1.13.jar:2.1.13]
34 at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
35ERROR [STREAM-IN-/10.64.0.232] 2016-07-05 16:16:44,871 StreamSession.java:505 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Streaming error occurred
36java.io.IOException: Connection reset by peer
37 at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[na:1.8.0_91]
38 at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[na:1.8.0_91]
39 at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) ~[na:1.8.0_91]
40 at sun.nio.ch.IOUtil.read(IOUtil.java:197) ~[na:1.8.0_91]
41 at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) ~[na:1.8.0_91]
42 at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:51) ~[apache-cassandra-2.1.13.jar:2.1.13]
43 at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:250) ~[apache-cassandra-2.1.13.jar:2.1.13]
44 at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
45ERROR [STREAM-IN-/10.64.0.230] 2016-07-05 16:16:44,871 StreamSession.java:505 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Streaming error occurred
46java.io.IOException: Connection reset by peer
47 at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[na:1.8.0_91]
48 at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[na:1.8.0_91]
49 at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) ~[na:1.8.0_91]
50 at sun.nio.ch.IOUtil.read(IOUtil.java:197) ~[na:1.8.0_91]
51 at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) ~[na:1.8.0_91]
52 at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:51) ~[apache-cassandra-2.1.13.jar:2.1.13]
53 at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:250) ~[apache-cassandra-2.1.13.jar:2.1.13]
54 at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
55ERROR [STREAM-OUT-/10.64.0.232] 2016-07-05 16:16:44,871 StreamSession.java:505 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Streaming error occurred
56java.io.IOException: Connection reset by peer
57 at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_91]
58 at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_91]
59 at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_91]
60 at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_91]
61 at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_91]
62 at java.nio.channels.Channels.writeFullyImpl(Channels.java:78) ~[na:1.8.0_91]
63 at java.nio.channels.Channels.writeFully(Channels.java:98) ~[na:1.8.0_91]
64 at java.nio.channels.Channels.access$000(Channels.java:61) ~[na:1.8.0_91]
65 at java.nio.channels.Channels$1.write(Channels.java:174) ~[na:1.8.0_91]
66 at java.io.OutputStream.write(OutputStream.java:75) ~[na:1.8.0_91]
67--
68ERROR [STREAM-OUT-/10.64.0.230] 2016-07-05 16:16:44,907 StreamSession.java:505 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Streaming error occurred
69java.io.IOException: Broken pipe
70 at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_91]
71 at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_91]
72 at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_91]
73 at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_91]
74 at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_91]
75 at org.apache.cassandra.io.util.DataOutputStreamAndChannel.write(DataOutputStreamAndChannel.java:48) ~[apache-cassandra-2.1.13.jar:2.1.13]
76 at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:44) ~[apache-cassandra-2.1.13.jar:2.1.13]
77 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:351) [apache-cassandra-2.1.13.jar:2.1.13]
78 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.run(ConnectionHandler.java:331) [apache-cassandra-2.1.13.jar:2.1.13]
79 at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
80ERROR [STREAM-OUT-/10.64.0.232] 2016-07-05 16:16:44,907 StreamSession.java:505 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Streaming error occurred
81java.io.IOException: Broken pipe
82 at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_91]
83 at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_91]
84 at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_91]
85 at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_91]
86 at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_91]
87 at org.apache.cassandra.io.util.DataOutputStreamAndChannel.write(DataOutputStreamAndChannel.java:48) ~[apache-cassandra-2.1.13.jar:2.1.13]
88 at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:44) ~[apache-cassandra-2.1.13.jar:2.1.13]
89 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:351) [apache-cassandra-2.1.13.jar:2.1.13]
90 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.run(ConnectionHandler.java:331) [apache-cassandra-2.1.13.jar:2.1.13]
91 at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
92ERROR [STREAM-OUT-/10.64.0.231] 2016-07-05 16:16:44,907 StreamSession.java:505 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Streaming error occurred
93java.io.IOException: Broken pipe
94 at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_91]
95 at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_91]
96 at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_91]
97 at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_91]
98 at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_91]
99 at org.apache.cassandra.io.util.DataOutputStreamAndChannel.write(DataOutputStreamAndChannel.java:48) ~[apache-cassandra-2.1.13.jar:2.1.13]
100 at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:44) ~[apache-cassandra-2.1.13.jar:2.1.13]
101 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:351) [apache-cassandra-2.1.13.jar:2.1.13]
102 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.run(ConnectionHandler.java:331) [apache-cassandra-2.1.13.jar:2.1.13]
103 at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]

Eevans added a comment.EditedJul 5 2016, 5:05 PM

With any luck this does not result in ~12 hours of streaming, only to fail for these (early) errors. Stay tuned...

Actually, after thinking about this more, I'm suspect this is exactly what will happen. The exceptions encountered during stream planning will prevent the bootstrap from completing (i.e. that it did not fail fast, but will fail).

Eevans moved this task from Backlog to In-Progress on the Cassandra board.Jul 6 2016, 2:57 AM

and indeed the bootstrap failed just now as reported below

1INFO [MemtableFlushWriter:404] 2016-07-06 11:47:46,177 Memtable.java:382 - Completed flushing /srv/cassandra-c/data/system/compactions_in_progress-55080ab05d9c388690a4acb25fe1f77b/system-compactions_in_progress-tmp-ka-25373-Data.db (0.000KiB) for commitlog position ReplayPosition(segmentId=1467734948851, position=11167676)
2INFO [CompactionExecutor:996] 2016-07-06 11:47:46,681 CompactionTask.java:274 - Compacted 2 sstables to [/srv/cassandra-c/data/local_group_default_T_mobileapps_lead/data-13482db08e0b11e5adc765f8a3ffd5d4/local_group_default_T_mobileapps_lead-data-ka-255,]. 89,074,993 bytes to 88,919,279 (~99% of original) in 46,803ms = 1.811850MB/s. 80,609 total partitions merged to 80,609. Partition merge counts were {1:80609, }
3INFO [CompactionExecutor:996] 2016-07-06 11:47:46,683 ColumnFamilyStore.java:905 - Enqueuing flush of compactions_in_progress: 293 (0%) on-heap, 210 (0%) off-heap
4INFO [MemtableFlushWriter:405] 2016-07-06 11:47:46,683 Memtable.java:347 - Writing Memtable-compactions_in_progress@1233203153(0.156KiB serialized bytes, 7 ops, 0%/0% of on/off-heap limit)
5INFO [MemtableFlushWriter:405] 2016-07-06 11:47:46,684 Memtable.java:382 - Completed flushing /srv/cassandra-c/data/system/compactions_in_progress-55080ab05d9c388690a4acb25fe1f77b/system-compactions_in_progress-tmp-ka-25374-Data.db (0.000KiB) for commitlog position ReplayPosition(segmentId=1467734948851, position=11309995)
6INFO [CompactionExecutor:996] 2016-07-06 11:47:47,132 CompactionTask.java:141 - Compacting [SSTableReader(path='/srv/cassandra-c/data/local_group_default_T_mobileapps_lead/data-13482db08e0b11e5adc765f8a3ffd5d4/local_group_default_T_mobileapps_lead-data-ka-230-Data.db'), SSTableReader(path='/srv/cassandra-c/data/local_group_default_T_mobileapps_lead/data-13482db08e0b11e5adc765f8a3ffd5d4/local_group_default_T_mobileapps_lead-data-ka-236-Data.db')]
7INFO [CompactionExecutor:996] 2016-07-06 11:47:56,929 ColumnFamilyStore.java:905 - Enqueuing flush of compactions_in_progress: 149 (0%) on-heap, 20 (0%) off-heap
8INFO [MemtableFlushWriter:404] 2016-07-06 11:47:56,929 Memtable.java:347 - Writing Memtable-compactions_in_progress@1840999663(0.008KiB serialized bytes, 1 ops, 0%/0% of on/off-heap limit)
9INFO [MemtableFlushWriter:404] 2016-07-06 11:47:56,930 Memtable.java:382 - Completed flushing /srv/cassandra-c/data/system/compactions_in_progress-55080ab05d9c388690a4acb25fe1f77b/system-compactions_in_progress-tmp-ka-25375-Data.db (0.000KiB) for commitlog position ReplayPosition(segmentId=1467734948851, position=17450860)
10INFO [CompactionExecutor:996] 2016-07-06 11:47:57,482 CompactionTask.java:274 - Compacted 2 sstables to [/srv/cassandra-c/data/local_group_default_T_mobileapps_lead/data-13482db08e0b11e5adc765f8a3ffd5d4/local_group_default_T_mobileapps_lead-data-ka-256,]. 17,080,181 bytes to 16,586,330 (~97% of original) in 10,350ms = 1.528305MB/s. 18,587 total partitions merged to 18,581. Partition merge counts were {1:18575, 2:6, }
11INFO [CompactionExecutor:996] 2016-07-06 11:47:57,483 CompactionTask.java:141 - Compacting [SSTableReader(path='/srv/cassandra-c/data/system/compactions_in_progress-55080ab05d9c388690a4acb25fe1f77b/system-compactions_in_progress-ka-25372-Data.db'), SSTableReader(path='/srv/cassandra-c/data/system/compactions_in_progress-55080ab05d9c388690a4acb25fe1f77b/system-compactions_in_progress-ka-25375-Data.db'), SSTableReader(path='/srv/cassandra-c/data/system/compactions_in_progress-55080ab05d9c388690a4acb25fe1f77b/system-compactions_in_progress-ka-25374-Data.db'), SSTableReader(path='/srv/cassandra-c/data/system/compactions_in_progress-55080ab05d9c388690a4acb25fe1f77b/system-compactions_in_progress-ka-25373-Data.db'), SSTableReader(path='/srv/cassandra-c/data/system/compactions_in_progress-55080ab05d9c388690a4acb25fe1f77b/system-compactions_in_progress-ka-25371-Data.db')]
12INFO [CompactionExecutor:996] 2016-07-06 11:47:58,319 CompactionTask.java:274 - Compacted 5 sstables to [/srv/cassandra-c/data/system/compactions_in_progress-55080ab05d9c388690a4acb25fe1f77b/system-compactions_in_progress-ka-25376,]. 1,220 bytes to 774 (~63% of original) in 836ms = 0.000883MB/s. 13 total partitions merged to 9. Partition merge counts were {1:9, 2:2, }
13INFO [CompactionExecutor:996] 2016-07-06 11:47:58,320 ColumnFamilyStore.java:905 - Enqueuing flush of compactions_in_progress: 293 (0%) on-heap, 210 (0%) off-heap
14INFO [MemtableFlushWriter:405] 2016-07-06 11:47:58,320 Memtable.java:347 - Writing Memtable-compactions_in_progress@1635680852(0.156KiB serialized bytes, 7 ops, 0%/0% of on/off-heap limit)
15INFO [MemtableFlushWriter:405] 2016-07-06 11:47:58,321 Memtable.java:382 - Completed flushing /srv/cassandra-c/data/system/compactions_in_progress-55080ab05d9c388690a4acb25fe1f77b/system-compactions_in_progress-tmp-ka-25377-Data.db (0.000KiB) for commitlog position ReplayPosition(segmentId=1467734948851, position=18041680)
16INFO [CompactionExecutor:996] 2016-07-06 11:47:58,902 CompactionTask.java:141 - Compacting [SSTableReader(path='/srv/cassandra-c/data/local_group_default_T_mobileapps_lead/data-13482db08e0b11e5adc765f8a3ffd5d4/local_group_default_T_mobileapps_lead-data-ka-256-Data.db'), SSTableReader(path='/srv/cassandra-c/data/local_group_default_T_mobileapps_lead/data-13482db08e0b11e5adc765f8a3ffd5d4/local_group_default_T_mobileapps_lead-data-ka-213-Data.db')]
17INFO [StreamReceiveTask:925] 2016-07-06 11:48:13,494 StreamResultFuture.java:180 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Session with /10.64.48.139 is complete
18WARN [StreamReceiveTask:925] 2016-07-06 11:48:13,542 StreamResultFuture.java:207 - [Stream #e2271d20-42ca-11e6-bec9-09a5662464fd] Stream failed
19ERROR [main] 2016-07-06 11:48:13,545 CassandraDaemon.java:581 - Exception encountered during startup
20java.lang.RuntimeException: Error during boostrap: Stream failed
21 at org.apache.cassandra.dht.BootStrapper.bootstrap(BootStrapper.java:86) ~[apache-cassandra-2.1.13.jar:2.1.13]
22 at org.apache.cassandra.service.StorageService.bootstrap(StorageService.java:1166) ~[apache-cassandra-2.1.13.jar:2.1.13]
23 at org.apache.cassandra.service.StorageService.joinTokenRing(StorageService.java:944) ~[apache-cassandra-2.1.13.jar:2.1.13]
24 at org.apache.cassandra.service.StorageService.initServer(StorageService.java:740) ~[apache-cassandra-2.1.13.jar:2.1.13]
25 at org.apache.cassandra.service.StorageService.initServer(StorageService.java:617) ~[apache-cassandra-2.1.13.jar:2.1.13]
26 at org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:389) [apache-cassandra-2.1.13.jar:2.1.13]
27 at org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:564) [apache-cassandra-2.1.13.jar:2.1.13]
28 at org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:653) [apache-cassandra-2.1.13.jar:2.1.13]
29Caused by: org.apache.cassandra.streaming.StreamException: Stream failed
30 at org.apache.cassandra.streaming.management.StreamEventJMXNotifier.onFailure(StreamEventJMXNotifier.java:85) ~[apache-cassandra-2.1.13.jar:2.1.13]
31 at com.google.common.util.concurrent.Futures$4.run(Futures.java:1172) ~[guava-16.0.jar:na]
32 at com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:297) ~[guava-16.0.jar:na]
33 at com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156) ~[guava-16.0.jar:na]
34 at com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145) ~[guava-16.0.jar:na]
35 at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:202) ~[guava-16.0.jar:na]
36 at org.apache.cassandra.streaming.StreamResultFuture.maybeComplete(StreamResultFuture.java:208) ~[apache-cassandra-2.1.13.jar:2.1.13]
37 at org.apache.cassandra.streaming.StreamResultFuture.handleSessionComplete(StreamResultFuture.java:184) ~[apache-cassandra-2.1.13.jar:2.1.13]
38 at org.apache.cassandra.streaming.StreamSession.closeSession(StreamSession.java:415) ~[apache-cassandra-2.1.13.jar:2.1.13]
39 at org.apache.cassandra.streaming.StreamSession.maybeCompleted(StreamSession.java:691) ~[apache-cassandra-2.1.13.jar:2.1.13]
40 at org.apache.cassandra.streaming.StreamSession.taskCompleted(StreamSession.java:652) ~[apache-cassandra-2.1.13.jar:2.1.13]
41 at org.apache.cassandra.streaming.StreamReceiveTask$OnCompletionRunnable.run(StreamReceiveTask.java:179) ~[apache-cassandra-2.1.13.jar:2.1.13]
42 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_91]
43 at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_91]
44 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_91]
45 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_91]
46 at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_91]
47WARN [StorageServiceShutdownHook] 2016-07-06 11:48:13,627 Gossiper.java:1463 - No local state or state is in silent shutdown, not announcing shutdown
48INFO [StorageServiceShutdownHook] 2016-07-06 11:48:13,628 MessagingService.java:734 - Waiting for messaging service to quiesce
49INFO [ACCEPT-/10.64.48.131] 2016-07-06 11:48:13,628 MessagingService.java:1018 - MessagingService has terminated the accept() thread
50INFO [ACCEPT-/10.64.48.131] 2016-07-06 11:48:13,665 MessagingService.java:1018 - MessagingService has terminated the accept() thread

At least the cluster is still functional. So now we can either revert 1007 back to 2.1.13 and bootstrap these or expedite the conversion to 2.2.6. I'd vote for the latter, but I guess that is highly dependant on the time frame for it. Thoughts?

mobrovac triaged this task as High priority.Jul 6 2016, 12:03 PM
mobrovac added a project: Operations.

Alternatively, would decommissioning rb1014-c help?

Eevans added a comment.Jul 6 2016, 2:31 PM

At least the cluster is still functional. So now we can either revert 1007 back to 2.1.13 and bootstrap these or expedite the conversion to 2.2.6. I'd vote for the latter, but I guess that is highly dependant on the time frame for it. Thoughts?

Reverting 1007 would be destructive to 3 instances. The worst-case scenario for 1014 is a removenode of one instance, also destructive, but to much less data.

Alternatively, would decommissioning rb1014-c help?

Unfortunately, I don't think it would. Some of that data would stream to 1014-{a,b} as well, and we'd have to wait for that to complete before starting a cleanup. We are very tight on space, I'm not sure a cleanup is possible with the current storage load, let alone after adding more.


I think our best bet is now Option 1 from above. Only, I want to amend that to omit the use of 'plow'; Now is not the time for haste.

I think it is unlikely that we will be able to get out of this without some replica loss on 1014. Even if we were able to start a cleanup now, it would be rough making progress with so little working space. I recommend that we proceed with the 2.2.6 upgrade. If we can get the entire cluster on 2.2.6, we can attempt a bootstrap of 1009-c and/or 1015-c, and attempt a cleanup at that time. If we cannot complete the upgrade before running out of space on 1014, we'll simply have to removenode one instance. Likewise, if we do complete the upgrade, and don't have the working space to make progress on the cleanup, a removenode will be necessary.

I don't think decommissioning would help, data would move off to other instances in rack d including 1014 to make space even tighter, until cleanups get a chance to run, assuming there's enough space

Change 297598 had a related patch set uploaded (by Eevans):
Revert "Bootstrap Cassandra instance restbase1009-c"

https://gerrit.wikimedia.org/r/297598

Change 297598 merged by Filippo Giunchedi:
Revert "Bootstrap Cassandra instance restbase1009-c"

https://gerrit.wikimedia.org/r/297598

Change 297905 had a related patch set uploaded (by Eevans):
Enable instance 1009-c

https://gerrit.wikimedia.org/r/297905

Change 297905 merged by Dzahn:
Enable instance 1009-c

https://gerrit.wikimedia.org/r/297905

Mentioned in SAL [2016-07-07T21:32:27Z] <urandom> Bootstrapping restbase1009-c : T139362

looks like the latest bootstrap failed too

1ERROR [STREAM-IN-/10.64.48.135] 2016-07-08 01:42:01,480 StreamSession.java:640 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Remote peer 10.64.48.135 failed stream session.
2WARN [CompactionExecutor:424] 2016-07-08 04:01:49,364 BigTableWriter.java:184 - Writing large partition local_group_wikipedia_T_parsoid_dataW4ULtxs1oMqJ/data:en.wikipedia.org:Wikipedia\:VIAF/errors (158159893 bytes)
3ERROR [STREAM-IN-/10.64.48.138] 2016-07-08 05:04:45,690 StreamSession.java:640 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Remote peer 10.64.48.138 failed stream session.
4ERROR [STREAM-IN-/10.64.48.120] 2016-07-08 05:19:13,758 StreamSession.java:640 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Remote peer 10.64.48.120 failed stream session.
5WARN [CompactionExecutor:424] 2016-07-08 05:43:22,045 BigTableWriter.java:184 - Writing large partition local_group_wikipedia_T_parsoid_dataW4ULtxs1oMqJ/data:en.wikipedia.org:Wikipedia\:JSTOR/Errors (216237951 bytes)
6ERROR [STREAM-IN-/10.64.48.137] 2016-07-08 07:15:54,599 StreamSession.java:640 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Remote peer 10.64.48.137 failed stream session.
7ERROR [STREAM-IN-/10.64.48.136] 2016-07-08 08:19:54,151 StreamSession.java:640 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Remote peer 10.64.48.136 failed stream session.
8ERROR [STREAM-IN-/10.64.48.130] 2016-07-08 08:41:04,719 StreamSession.java:640 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Remote peer 10.64.48.130 failed stream session.
9ERROR [STREAM-IN-/10.64.48.139] 2016-07-08 09:02:16,004 StreamSession.java:640 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Remote peer 10.64.48.139 failed stream session.
10ERROR [main] 2016-07-08 09:02:16,333 StorageService.java:1268 - Error while waiting on bootstrap to complete. Bootstrap will have to be restarted.
11
12
13
14== 1009 errors
15
16restbase1009:/var/log/cassandra$ grep -A10 'ERROR.*fe6ff550-4488-11e6-85be-e77a66119977' system-a.log
17ERROR [STREAM-IN-/10.64.48.131] 2016-07-08 04:52:09,525 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
18java.net.SocketTimeoutException: null
19 at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:211) ~[na:1.8.0_91]
20 at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103) ~[na:1.8.0_91]
21 at java.nio.channels.Channels$ReadableByteChannelImpl.read(Channels.java:385) ~[na:1.8.0_91]
22 at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:53) ~[apache-cassandra-2.2.6.jar:2.2.6]
23 at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:268) ~[apache-cassandra-2.2.6.jar:2.2.6]
24 at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
25WARN [CompactionExecutor:3022] 2016-07-08 05:00:01,284 BigTableWriter.java:184 - Writing large partition system/hints:c42d329c-68d5-4d1b-b886-90aa752fb288 (522455462 bytes)
26WARN [HintedHandoffManager:1] 2016-07-08 05:00:03,875 HintedHandoffMetrics.java:80 - /10.192.32.125 has 1626 dropped hints, because node is down past configured hint window.
27INFO [Service Thread] 2016-07-08 05:08:53,571 GCInspector.java:284 - G1 Young Generation GC in 226ms. G1 Eden Space: 7281311744 -> 0; G1 Old Gen: 2868728320 -> 2878496264; G1 Survivor Space: 444596224 -> 629145600;
28--
29ERROR [STREAM-OUT-/10.64.48.131] 2016-07-08 05:19:12,232 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
30java.lang.AssertionError: Memory was freed
31 at org.apache.cassandra.io.util.SafeMemory.checkBounds(SafeMemory.java:103) ~[apache-cassandra-2.2.6.jar:2.2.6]
32 at org.apache.cassandra.io.util.Memory.getLong(Memory.java:260) ~[apache-cassandra-2.2.6.jar:2.2.6]
33 at org.apache.cassandra.io.compress.CompressionMetadata.getTotalSizeForSections(CompressionMetadata.java:247) ~[apache-cassandra-2.2.6.jar:2.2.6]
34 at org.apache.cassandra.streaming.messages.FileMessageHeader.size(FileMessageHeader.java:125) ~[apache-cassandra-2.2.6.jar:2.2.6]
35 at org.apache.cassandra.streaming.StreamSession.fileSent(StreamSession.java:565) ~[apache-cassandra-2.2.6.jar:2.2.6]
36 at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:49) ~[apache-cassandra-2.2.6.jar:2.2.6]
37 at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:40) ~[apache-cassandra-2.2.6.jar:2.2.6]
38 at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:47) ~[apache-cassandra-2.2.6.jar:2.2.6]
39 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:370) ~[apache-cassandra-2.2.6.jar:2.2.6]
40restbase1009:/var/log/cassandra$ grep -A10 'ERROR.*fe6ff550-4488-11e6-85be-e77a66119977' system-b.log
41ERROR [STREAM-IN-/10.64.48.131] 2016-07-08 06:08:48,272 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
42java.net.SocketTimeoutException: null
43 at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:211) ~[na:1.8.0_91]
44 at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103) ~[na:1.8.0_91]
45 at java.nio.channels.Channels$ReadableByteChannelImpl.read(Channels.java:385) ~[na:1.8.0_91]
46 at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:53) ~[apache-cassandra-2.2.6.jar:2.2.6]
47 at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:268) ~[apache-cassandra-2.2.6.jar:2.2.6]
48 at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
49INFO [ScheduledTasks:1] 2016-07-08 06:11:08,316 MessagingService.java:946 - MUTATION messages were dropped in last 5000 ms: 18 for internal timeout and 0 for cross node timeout
50INFO [ScheduledTasks:1] 2016-07-08 06:11:08,316 StatusLogger.java:52 - Pool Name Active Pending Completed Blocked All Time Blocked
51INFO [ScheduledTasks:1] 2016-07-08 06:11:08,331 StatusLogger.java:56 - MutationStage 0 0 7103724 0 0
52--
53ERROR [STREAM-OUT-/10.64.48.131] 2016-07-08 08:41:03,235 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
54java.lang.AssertionError: Memory was freed
55 at org.apache.cassandra.io.util.SafeMemory.checkBounds(SafeMemory.java:103) ~[apache-cassandra-2.2.6.jar:2.2.6]
56 at org.apache.cassandra.io.util.Memory.getLong(Memory.java:260) ~[apache-cassandra-2.2.6.jar:2.2.6]
57 at org.apache.cassandra.io.compress.CompressionMetadata.getTotalSizeForSections(CompressionMetadata.java:247) ~[apache-cassandra-2.2.6.jar:2.2.6]
58 at org.apache.cassandra.streaming.messages.FileMessageHeader.size(FileMessageHeader.java:125) ~[apache-cassandra-2.2.6.jar:2.2.6]
59 at org.apache.cassandra.streaming.StreamSession.fileSent(StreamSession.java:565) ~[apache-cassandra-2.2.6.jar:2.2.6]
60 at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:49) ~[apache-cassandra-2.2.6.jar:2.2.6]
61 at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:40) ~[apache-cassandra-2.2.6.jar:2.2.6]
62 at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:47) ~[apache-cassandra-2.2.6.jar:2.2.6]
63 at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:370) ~[apache-cassandra-2.2.6.jar:2.2.6]
64restbase1009:/var/log/cassandra$
65
66
67== 1015 errors
68restbase1015:/var/log/cassandra$ grep -A10 'ERROR.*fe6ff550-4488-11e6-85be-e77a66119977' system-*.log
69system-a.log:ERROR [STREAM-IN-/10.64.48.131] 2016-07-08 04:52:21,348 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
70system-a.log-java.net.SocketTimeoutException: null
71system-a.log- at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:211) ~[na:1.8.0_91]
72system-a.log- at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103) ~[na:1.8.0_91]
73system-a.log- at java.nio.channels.Channels$ReadableByteChannelImpl.read(Channels.java:385) ~[na:1.8.0_91]
74system-a.log- at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:53) ~[apache-cassandra-2.2.6.jar:2.2.6]
75system-a.log- at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:268) ~[apache-cassandra-2.2.6.jar:2.2.6]
76system-a.log- at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
77system-a.log-WARN [CompactionExecutor:1014] 2016-07-08 04:57:00,626 BigTableWriter.java:184 - Writing large partition system/hints:c42d329c-68d5-4d1b-b886-90aa752fb288 (459981414 bytes)
78system-a.log-WARN [HintedHandoffManager:1] 2016-07-08 04:57:01,777 HintedHandoffMetrics.java:80 - /10.192.32.125 has 1150 dropped hints, because node is down past configured hint window.
79system-a.log-INFO [STREAM-IN-/10.64.48.131] 2016-07-08 05:04:45,446 StreamResultFuture.java:182 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Session with /10.64.48.131 is complete
80system-a.log:ERROR [STREAM-OUT-/10.64.48.131] 2016-07-08 05:04:45,490 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
81system-a.log-java.lang.AssertionError: Memory was freed
82system-a.log- at org.apache.cassandra.io.util.SafeMemory.checkBounds(SafeMemory.java:103) ~[apache-cassandra-2.2.6.jar:2.2.6]
83system-a.log- at org.apache.cassandra.io.util.Memory.getLong(Memory.java:260) ~[apache-cassandra-2.2.6.jar:2.2.6]
84system-a.log- at org.apache.cassandra.io.compress.CompressionMetadata.getTotalSizeForSections(CompressionMetadata.java:247) ~[apache-cassandra-2.2.6.jar:2.2.6]
85system-a.log- at org.apache.cassandra.streaming.messages.FileMessageHeader.size(FileMessageHeader.java:125) ~[apache-cassandra-2.2.6.jar:2.2.6]
86system-a.log- at org.apache.cassandra.streaming.StreamSession.fileSent(StreamSession.java:565) ~[apache-cassandra-2.2.6.jar:2.2.6]
87system-a.log- at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:49) ~[apache-cassandra-2.2.6.jar:2.2.6]
88system-a.log- at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:40) ~[apache-cassandra-2.2.6.jar:2.2.6]
89system-a.log- at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:47) ~[apache-cassandra-2.2.6.jar:2.2.6]
90system-a.log- at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:370) ~[apache-cassandra-2.2.6.jar:2.2.6]
91--
92system-b.log:ERROR [STREAM-IN-/10.64.48.131] 2016-07-08 08:36:04,965 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
93system-b.log-java.net.SocketTimeoutException: null
94system-b.log- at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:211) ~[na:1.8.0_91]
95system-b.log- at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103) ~[na:1.8.0_91]
96system-b.log- at java.nio.channels.Channels$ReadableByteChannelImpl.read(Channels.java:385) ~[na:1.8.0_91]
97system-b.log- at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:53) ~[apache-cassandra-2.2.6.jar:2.2.6]
98system-b.log- at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:268) ~[apache-cassandra-2.2.6.jar:2.2.6]
99system-b.log- at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
100system-b.log-INFO [Service Thread] 2016-07-08 08:43:53,716 GCInspector.java:284 - G1 Young Generation GC in 216ms. G1 Eden Space: 7306477568 -> 0; G1 Old Gen: 2637334528 -> 2649365512; G1 Survivor Space: 419430400 -> 427819008;
101system-b.log-INFO [Service Thread] 2016-07-08 08:43:53,717 StatusLogger.java:52 - Pool Name Active Pending Completed Blocked All Time Blocked
102system-b.log-INFO [Service Thread] 2016-07-08 08:43:53,733 StatusLogger.java:56 - MutationStage 0 0 3571809 0 0
103--
104system-b.log:ERROR [STREAM-OUT-/10.64.48.131] 2016-07-08 09:02:15,276 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
105system-b.log-java.lang.AssertionError: Memory was freed
106system-b.log- at org.apache.cassandra.io.util.SafeMemory.checkBounds(SafeMemory.java:103) ~[apache-cassandra-2.2.6.jar:2.2.6]
107system-b.log- at org.apache.cassandra.io.util.Memory.getLong(Memory.java:260) ~[apache-cassandra-2.2.6.jar:2.2.6]
108system-b.log- at org.apache.cassandra.io.compress.CompressionMetadata.getTotalSizeForSections(CompressionMetadata.java:247) ~[apache-cassandra-2.2.6.jar:2.2.6]
109system-b.log- at org.apache.cassandra.streaming.messages.FileMessageHeader.size(FileMessageHeader.java:125) ~[apache-cassandra-2.2.6.jar:2.2.6]
110system-b.log- at org.apache.cassandra.streaming.StreamSession.fileSent(StreamSession.java:565) ~[apache-cassandra-2.2.6.jar:2.2.6]
111system-b.log- at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:49) ~[apache-cassandra-2.2.6.jar:2.2.6]
112system-b.log- at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:40) ~[apache-cassandra-2.2.6.jar:2.2.6]
113system-b.log- at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:47) ~[apache-cassandra-2.2.6.jar:2.2.6]
114system-b.log- at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:370) ~[apache-cassandra-2.2.6.jar:2.2.6]
115
116
117== 1014 errors
118
119restbase1014:~$ grep -A10 'ERROR.*fe6ff550-4488-11e6-85be-e77a66119977' /var/log/cassandra/system*.log
120/var/log/cassandra/system-a.log:ERROR [STREAM-IN-/10.64.48.131] 2016-07-08 01:38:25,913 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
121/var/log/cassandra/system-a.log-java.net.SocketTimeoutException: null
122/var/log/cassandra/system-a.log- at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:211) ~[na:1.8.0_91]
123/var/log/cassandra/system-a.log- at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103) ~[na:1.8.0_91]
124/var/log/cassandra/system-a.log- at java.nio.channels.Channels$ReadableByteChannelImpl.read(Channels.java:385) ~[na:1.8.0_91]
125/var/log/cassandra/system-a.log- at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:53) ~[apache-cassandra-2.2.6.jar:2.2.6]
126/var/log/cassandra/system-a.log- at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:268) ~[apache-cassandra-2.2.6.jar:2.2.6]
127/var/log/cassandra/system-a.log- at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
128/var/log/cassandra/system-a.log-WARN [CompactionExecutor:754] 2016-07-08 01:38:40,238 BigTableWriter.java:184 - Writing large partition system/hints:c42d329c-68d5-4d1b-b886-90aa752fb288 (479449765 bytes)
129/var/log/cassandra/system-a.log-WARN [HintedHandoffManager:1] 2016-07-08 01:38:41,811 HintedHandoffMetrics.java:80 - /10.192.32.125 has 1023 dropped hints, because node is down past configured hint window.
130/var/log/cassandra/system-a.log-INFO [Service Thread] 2016-07-08 01:39:51,466 GCInspector.java:284 - G1 Young Generation GC in 273ms. G1 Eden Space: 234881024 -> 0; G1 Old Gen: 4449695232 -> 3577995792; G1 Survivor Space: 402653184 -> 83886080;
131--
132/var/log/cassandra/system-a.log:ERROR [STREAM-OUT-/10.64.48.131] 2016-07-08 01:41:58,727 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
133/var/log/cassandra/system-a.log-java.lang.AssertionError: Memory was freed
134/var/log/cassandra/system-a.log- at org.apache.cassandra.io.util.SafeMemory.checkBounds(SafeMemory.java:103) ~[apache-cassandra-2.2.6.jar:2.2.6]
135/var/log/cassandra/system-a.log- at org.apache.cassandra.io.util.Memory.getLong(Memory.java:260) ~[apache-cassandra-2.2.6.jar:2.2.6]
136/var/log/cassandra/system-a.log- at org.apache.cassandra.io.compress.CompressionMetadata.getTotalSizeForSections(CompressionMetadata.java:247) ~[apache-cassandra-2.2.6.jar:2.2.6]
137/var/log/cassandra/system-a.log- at org.apache.cassandra.streaming.messages.FileMessageHeader.size(FileMessageHeader.java:125) ~[apache-cassandra-2.2.6.jar:2.2.6]
138/var/log/cassandra/system-a.log- at org.apache.cassandra.streaming.StreamSession.fileSent(StreamSession.java:565) ~[apache-cassandra-2.2.6.jar:2.2.6]
139/var/log/cassandra/system-a.log- at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:49) ~[apache-cassandra-2.2.6.jar:2.2.6]
140/var/log/cassandra/system-a.log- at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:40) ~[apache-cassandra-2.2.6.jar:2.2.6]
141/var/log/cassandra/system-a.log- at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:47) ~[apache-cassandra-2.2.6.jar:2.2.6]
142/var/log/cassandra/system-a.log- at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:370) ~[apache-cassandra-2.2.6.jar:2.2.6]
143--
144/var/log/cassandra/system-b.log:ERROR [STREAM-IN-/10.64.48.131] 2016-07-08 07:34:03,374 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
145/var/log/cassandra/system-b.log-java.net.SocketTimeoutException: null
146/var/log/cassandra/system-b.log- at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:211) ~[na:1.8.0_91]
147/var/log/cassandra/system-b.log- at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103) ~[na:1.8.0_91]
148/var/log/cassandra/system-b.log- at java.nio.channels.Channels$ReadableByteChannelImpl.read(Channels.java:385) ~[na:1.8.0_91]
149/var/log/cassandra/system-b.log- at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:53) ~[apache-cassandra-2.2.6.jar:2.2.6]
150/var/log/cassandra/system-b.log- at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:268) ~[apache-cassandra-2.2.6.jar:2.2.6]
151/var/log/cassandra/system-b.log- at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
152/var/log/cassandra/system-b.log-WARN [CompactionExecutor:1268] 2016-07-08 07:35:24,585 BigTableWriter.java:184 - Writing large partition system/hints:c42d329c-68d5-4d1b-b886-90aa752fb288 (635270451 bytes)
153/var/log/cassandra/system-b.log-WARN [HintedHandoffManager:1] 2016-07-08 07:35:28,560 HintedHandoffMetrics.java:80 - /10.192.32.125 has 2511 dropped hints, because node is down past configured hint window.
154/var/log/cassandra/system-b.log-WARN [CompactionExecutor:1277] 2016-07-08 07:45:42,224 BigTableWriter.java:184 - Writing large partition system/hints:c42d329c-68d5-4d1b-b886-90aa752fb288 (635270451 bytes)
155--
156/var/log/cassandra/system-b.log:ERROR [STREAM-OUT-/10.64.48.131] 2016-07-08 08:19:52,364 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
157/var/log/cassandra/system-b.log-java.lang.AssertionError: Memory was freed
158/var/log/cassandra/system-b.log- at org.apache.cassandra.io.util.SafeMemory.checkBounds(SafeMemory.java:103) ~[apache-cassandra-2.2.6.jar:2.2.6]
159/var/log/cassandra/system-b.log- at org.apache.cassandra.io.util.Memory.getLong(Memory.java:260) ~[apache-cassandra-2.2.6.jar:2.2.6]
160/var/log/cassandra/system-b.log- at org.apache.cassandra.io.compress.CompressionMetadata.getTotalSizeForSections(CompressionMetadata.java:247) ~[apache-cassandra-2.2.6.jar:2.2.6]
161/var/log/cassandra/system-b.log- at org.apache.cassandra.streaming.messages.FileMessageHeader.size(FileMessageHeader.java:125) ~[apache-cassandra-2.2.6.jar:2.2.6]
162/var/log/cassandra/system-b.log- at org.apache.cassandra.streaming.StreamSession.fileSent(StreamSession.java:565) ~[apache-cassandra-2.2.6.jar:2.2.6]
163/var/log/cassandra/system-b.log- at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:49) ~[apache-cassandra-2.2.6.jar:2.2.6]
164/var/log/cassandra/system-b.log- at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:40) ~[apache-cassandra-2.2.6.jar:2.2.6]
165/var/log/cassandra/system-b.log- at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:47) ~[apache-cassandra-2.2.6.jar:2.2.6]
166/var/log/cassandra/system-b.log- at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:370) ~[apache-cassandra-2.2.6.jar:2.2.6]
167--
168/var/log/cassandra/system-c.log:ERROR [STREAM-IN-/10.64.48.131] 2016-07-08 05:00:55,586 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
169/var/log/cassandra/system-c.log-java.net.SocketTimeoutException: null
170/var/log/cassandra/system-c.log- at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:211) ~[na:1.8.0_91]
171/var/log/cassandra/system-c.log- at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103) ~[na:1.8.0_91]
172/var/log/cassandra/system-c.log- at java.nio.channels.Channels$ReadableByteChannelImpl.read(Channels.java:385) ~[na:1.8.0_91]
173/var/log/cassandra/system-c.log- at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:53) ~[apache-cassandra-2.2.6.jar:2.2.6]
174/var/log/cassandra/system-c.log- at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:268) ~[apache-cassandra-2.2.6.jar:2.2.6]
175/var/log/cassandra/system-c.log- at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
176/var/log/cassandra/system-c.log-WARN [CompactionExecutor:1070] 2016-07-08 05:06:02,662 BigTableWriter.java:184 - Writing large partition system/hints:c42d329c-68d5-4d1b-b886-90aa752fb288 (495145104 bytes)
177/var/log/cassandra/system-c.log-WARN [HintedHandoffManager:1] 2016-07-08 05:06:04,403 HintedHandoffMetrics.java:80 - /10.192.32.125 has 1346 dropped hints, because node is down past configured hint window.
178/var/log/cassandra/system-c.log-INFO [Service Thread] 2016-07-08 05:15:30,610 GCInspector.java:284 - G1 Young Generation GC in 260ms. G1 Eden Space: 7365197824 -> 0; G1 Old Gen: 3683555312 -> 3690173440; G1 Survivor Space: 268435456 -> 260046848;
179--
180/var/log/cassandra/system-c.log:ERROR [STREAM-OUT-/10.64.48.131] 2016-07-08 07:15:52,729 StreamSession.java:524 - [Stream #fe6ff550-4488-11e6-85be-e77a66119977] Streaming error occurred
181/var/log/cassandra/system-c.log-java.lang.AssertionError: Memory was freed
182/var/log/cassandra/system-c.log- at org.apache.cassandra.io.util.Memory.checkBounds(Memory.java:338) ~[apache-cassandra-2.2.6.jar:2.2.6]
183/var/log/cassandra/system-c.log- at org.apache.cassandra.io.util.Memory.getLong(Memory.java:260) ~[apache-cassandra-2.2.6.jar:2.2.6]
184/var/log/cassandra/system-c.log- at org.apache.cassandra.io.compress.CompressionMetadata.getTotalSizeForSections(CompressionMetadata.java:247) ~[apache-cassandra-2.2.6.jar:2.2.6]
185/var/log/cassandra/system-c.log- at org.apache.cassandra.streaming.messages.FileMessageHeader.size(FileMessageHeader.java:125) ~[apache-cassandra-2.2.6.jar:2.2.6]
186/var/log/cassandra/system-c.log- at org.apache.cassandra.streaming.StreamSession.fileSent(StreamSession.java:565) ~[apache-cassandra-2.2.6.jar:2.2.6]
187/var/log/cassandra/system-c.log- at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:49) ~[apache-cassandra-2.2.6.jar:2.2.6]
188/var/log/cassandra/system-c.log- at org.apache.cassandra.streaming.messages.OutgoingFileMessage$1.serialize(OutgoingFileMessage.java:40) ~[apache-cassandra-2.2.6.jar:2.2.6]
189/var/log/cassandra/system-c.log- at org.apache.cassandra.streaming.messages.StreamMessage.serialize(StreamMessage.java:47) ~[apache-cassandra-2.2.6.jar:2.2.6]
190/var/log/cassandra/system-c.log- at org.apache.cassandra.streaming.ConnectionHandler$OutgoingMessageHandler.sendMessage(ConnectionHandler.java:370) ~[apache-cassandra-2.2.6.jar:2.2.6]
191

and the "memory was freed" + sockettimeout seem to point to bugs like https://issues.apache.org/jira/browse/CASSANDRA-11345 and related https://issues.apache.org/jira/browse/CASSANDRA-8343

Eevans added a comment.Jul 8 2016, 2:49 PM

looks like the latest bootstrap failed too

[ ... ]

and the "memory was freed" + sockettimeout seem to point to bugs like https://issues.apache.org/jira/browse/CASSANDRA-11345 and related https://issues.apache.org/jira/browse/CASSANDRA-8343

Yes, CASSANDRA-8343 does seem applicable here, in particular that a sockettimeout would be generated for a file that took longer than streaming_socket_timeout_in_ms to complete.

Background: This bootstrap was wreaking havoc on the participating machines, 1009 in particular (high cpu utilization, iowait, etc). This was creating high columnfamily and client request latency, which in turn was driving up RESTBase latency. I throttled the streams way back as a result (to 15mbit). I imagine this must have pushed the largest transfers to more than 1 hour in length (the default timeout), causing these failures.

I've resumed the bootstrap (you can resume now!), but suspect it will just fail once more.


1014 is now at 96% utilization (204G free). Assuming we could increase streaming_socket_timeout_in_ms, and or increase the stream throughput so that the bootstrap succeeds, it's likely to be quite late in the afternoon (early Saturday morning EU) before it completes, which would require us to nurse the cleanups throughout the weekend (a process that I believe will likely fail anyway).

Perhaps it's time to call it, and employ the nuclear option (aka nodetool removenode).

@mobrovac, @fgiunchedi ?

indeed sounds like 1014 won't be able to recover the disk space anyway on its own, I'm ok to go removenode

Change 297993 had a related patch set uploaded (by Eevans):
Deinit 1009-c and 1014-c

https://gerrit.wikimedia.org/r/297993

indeed sounds like 1014 won't be able to recover the disk space anyway on its own, I'm ok to go removenode

Precisely. +1 from me too

Change 297993 merged by Filippo Giunchedi:
Deinit 1009-c and 1014-c

https://gerrit.wikimedia.org/r/297993

Mentioned in SAL [2016-07-08T18:39:11Z] <urandom> Stopping restbase1014-c.eqiad.wmnet : T139362

Mentioned in SAL [2016-07-08T18:48:38Z] <urandom> "This is going to hurt me more than it does you."; `nodetool removenode' of restbase1014-c.eqiad.wmnet : T139362

Mentioned in SAL [2016-07-08T19:56:17Z] <urandom> Throttle RESTBase Cassandra outgoing streams to 3mbit cluster-wide : T139362

Eevans added a comment.Jul 8 2016, 8:09 PM

Status Update:

The Good News: A nodetool removenode for restbase1014-c.eqiad.wmnet has been initiated, and the space consumed by this instance has been reclaimed.

The Bad News: Until/unless a force is issued (i.e. nodetool removenode force), Cassandra will attempt to stream data from intact replicas to the newly calculated locations. In this case, the stream destinations are obviously the 6 remaining replicas in rack 'd' (restbase1009-{a,b}, and restbase101[4-5]-{a,b}). However, unlike a bootstrap, the stream sources here are taken from all over the cluster. As of this time, I am seeing as many as 23 incoming streams to individual instances in rack 'd'. This has driven utilization quite high and, unsurprisingly, latency as well. I am currently in the process of trying to throttle stream throughput low enough that latency is kept within acceptable limits. If unsuccessful I will force. Stay tuned...

Mentioned in SAL [2016-07-08T20:51:32Z] <urandom> Throttle RESTBase Cassandra outgoing streams to 1mbit cluster-wide : T139362 (actually happened at 21:26)

Mentioned in SAL [2016-07-08T20:59:50Z] <urandom> Forcing node removal (restbase1014-c.eqiad.wmnet) : T139362

Mentioned in SAL [2016-07-08T21:04:28Z] <urandom> Restarting restbase1009-a.eqiad.wmnet to cancel running streams : T139362

Mentioned in SAL [2016-07-08T21:10:59Z] <urandom> Restarting restbase1014-a.eqiad.wmnet to cancel running streams : T139362

Mentioned in SAL [2016-07-08T21:17:18Z] <urandom> Restarting restbase1015-a.eqiad.wmnet to cancel running streams : T139362

Mentioned in SAL [2016-07-08T21:48:05Z] <urandom> Restarting restbase1009-b.eqiad.wmnet to cancel running streams : T139362

Mentioned in SAL [2016-07-08T22:13:42Z] <urandom> Restarting restbase1014-b.eqiad.wmnet to cancel running streams : T139362

Mentioned in SAL [2016-07-08T22:59:35Z] <urandom> Restarting restbase1015-b.eqiad.wmnet to cancel running streams : T139362

Eevans closed this task as Resolved.Jul 9 2016, 12:22 AM