Details
-
Bug
-
Status: Resolved
-
Normal
-
Resolution: Fixed
-
None
-
Code
-
Normal
-
Normal
-
User Report
-
All
-
None
-
Description
The issue is when there are interleaving logs, then the filter here doesn't help.
I managed to reproduce the issue only once.
But I found logs from old CircleCI run. Please see logs/org.apache.cassandra.distributed.test.NetstatsBootstrapWithoutEntireSSTablesCompressionStreamingTest/<main>/<main>/system.log
The excerpt that shows what I am talking about:
DEBUG [node1_NettyStreaming-Outbound-/127.0.0.2.7012:1] node1 2021-03-17 22:41:21,057 CassandraCompressedStreamWriter.java:102 - [Stream #e3d93810-8771-11eb-a0f1-f756ef192fe7] Finished streaming file /tmp/dtests9118120876279144235/node1/data1/netstats_test/test_table-c0f7eda0877111ebbfc147ef604f6105/na-11-big-Data.db to /127.0.0.2:7012, bytesTransferred = 66.646KiB, totalSize = 66.646KiB
Bootstrap e3d93810-8771-11eb-a0f1-f756ef192fe7
/127.0.0.2
Sending 15 files, 1339433 bytes total. Already sent 3 files (20.00%), 197286 bytes total (14.73%)
DEBUG [Stream-Deserializer-/127.0.0.1:7012-2bcb5810] node2 2021-03-17 22:41:21,057 StreamingInboundHandler.java:187 - [Stream #e3d93810-8771-11eb-a0f1-f756ef192fe7 channel: 2bcb5810] Received IncomingStreamMessage{header=Header (tableId: c0f7eda0-8771-11eb-bfc1-47ef604f6105, #1, repairedAt: 0, pendingRepair: null, sendByFollower: true), stream=CassandraIncomingFile{sstable=netstats_test/test_table}}
DEBUG [Stream-Deserializer-/127.0.0.1:7012-2bcb5810] node2 2021-03-17 22:41:21,058 NettyStreamingMessageSender.java:258 - [Stream #e3d93810-8771-11eb-a0f1-f756ef192fe7 channel: 09fdf87e] Sending Received (c0f7eda0-8771-11eb-bfc1-47ef604f6105, #1)
/tmp/dtests9118120876279144235/node1/data1/system_auth/roles-5bc52802de2535edaeab188eecebb090/na-2-big-Data.db 102/102 bytes (100%) sent to idx:0/127.0.0.2
/tmp/dtests9118120876279144235/node1/data1/netstats_test/test_table-c0f7eda0877111ebbfc147ef604f6105/na-11-big-Data.db 65536/68246 bytes (96%) sent to idx:0/127.0.0.2
/tmp/dtests9118120876279144235/node1/data1/netstats_test/test_table-c0f7eda0877111ebbfc147ef604f6105/na-20-big-Data.db 62836/62836 bytes (100%) sent to idx:0/127.0.0.2
/tmp/dtests9118120876279144235/node1/data1/netstats_test/test_table-c0f7eda0877111ebbfc147ef604f6105/na-17-big-Data.db 68812/68812 bytes (100%) sent to idx:0/127.0.0.2
Read Repair Statistics:
Attempted: 0
Mismatch (Blocking): 0
Mismatch (Background): 0
Pool Name DEBUG [node1_NettyStreaming-Outbound-/127.0.0.2.7012:1] node1 2021-03-17 22:41:21,058 CassandraCompressedStreamWriter.java:64 - [Stream #e3d93810-8771-11eb-a0f1-f756ef192fe7] Start streaming file /tmp/dtests9118120876279144235/node1/data1/netstats_test/test_table-c0f7eda0877111ebbfc147ef604f6105/na-8-big-Data.db to /127.0.0.2:7012, repairedAt = 0, totalSize = 67504
Active PendingDEBUG [Stream-Deserializer-/127.0.0.1:7012-2bcb5810] node2 2021-03-17 22:41:21,058 StreamReceiveTask.java:88 - received 2 of 14 total files, 131648 of total bytes 68812
Completed Dropped
Large messages n/a 0 0 0
Small messages n/a 0 1 0
DEBUG [node1_NettyStreaming-Outbound-/127.0.0.2.7012:1] node1 2021-03-17 22:41:21,058 CassandraCompressedStreamWriter.java:81 - [Stream #e3d93810-8771-11eb-a0f1-f756ef192fe7] Writing section 0 with length 67504 to stream.
Gossip messages n/a 0 54 0
INFO [pool-2-thread-2] <main> 2021-03-17 22:41:21,567 /127.0.0.1:7012 Mode: NORMAL
The line Pool Name Active Pending Completed Dropped is split into three parts due to DEBUG logs interleaving and the filter doesn't remove Completed Dropped which is added to the results here which leads to the following exception
CC yifanc as he was working on CASSANDRA-16057
and stefan.miklosovic as the original author of these tests, if you guys know something I am missing here