Cassandra looping on uncommited paxos data merge task for reaper_db.running_repairs after latest update

[alextechnology]

Project board link

Ever since the last update to reaper, I've noticed all Cassandra cluster nodes stuck on a Paxos cleanup loop following the successful completion of weekend repair jobs. At first, I thought it might be related to scheduling a repair on the reaper_db keyspace, but even after deleting that schedule, this keeps happening. A restart of the cluster nodes does not resolve the issue. The only solution has been to TRUNCATE TABLE on reaper_db.running repairs and on system.paxos (an idea I got from here, even though I don't see the alarming metrics for paxos described: Lightweight transactions failing, conditional writes not getting processed )

Here is the end of the system.log file from one cassandra node showing a few repeats of the Paxos cleanup message and including log lines after issuing the TRUNCATE TABLE commands above. You can see that the Paxos Cleanup never seems to succeed for some reason. Worth noting is that we don't use any lightweight transactions with this Cassandra cluster, except for any implicit LWTs that are part of Reaper's scheduled repairs.

INFO [ScheduledTasks:1] 2023-08-21 14:13:43,277 UncommittedTableData.java:567 - Scheduling uncommitted paxos data merge task for reaper_db.running_repairs INFO [OptionalTasks:1] 2023-08-21 14:13:43,280 PaxosCleanupLocalCoordinator.java:89 - Completing uncommitted paxos instances for reaper_db.running_repairs on ranges [(8949321254197623629,-9213432971660673857], (-9213432971660673857,-9192933261965959677], (-9192933261965959677,-8982706794757326805], (-8982706794757326805,-8832914117334669911], (-8832914117334669911,-8618130602700274606], (-8618130602700274606,-8552493702724506721], (-8552493702724506721,-8246791102046433164], (-8246791102046433164,-8170782611032428675], (-8170782611032428675,-8137677090435094317], (-8137677090435094317,-7934512670822306643], (-7934512670822306643,-7480993086384473908], (-7480993086384473908,-7401761397724200676], (-7401761397724200676,-7167418294598831506], (-7167418294598831506,-7108430211362077135], (-7108430211362077135,-6870171681049243246], (-6870171681049243246,-6741066273187288577], (-6741066273187288577,-6463141681642046892], (-6463141681642046892,-6322388590276599019], (-6322388590276599019,-5970303671972182143], (-5970303671972182143,-5923898288918239532], (-5923898288918239532,-5645469749029696098], (-5645469749029696098,-5572111350008274197], (-5572111350008274197,-5078868584596007045], (-5078868584596007045,-5050167380069296847], (-5050167380069296847,-4956534045839704033], (-4956534045839704033,-4569713867804116558], (-4569713867804116558,-4522987549679083109], (-4522987549679083109,-4138387943017099459], (-4138387943017099459,-4111504341517471547], (-4111504341517471547,-3833798175093222917], (-3833798175093222917,-3587074376887567689], (-3587074376887567689,-3424092478619438466], (-3424092478619438466,-3366529493325805395], (-3366529493325805395,-3173103050556310818], (-3173103050556310818,-3171436717315927809], (-3171436717315927809,-2754425367645621260], (-2754425367645621260,-2521499789003572909], (-2521499789003572909,-2306854027747740872], (-2306854027747740872,-2004148127377296438], (-2004148127377296438,-1959756370643946664], (-1959756370643946664,-1747506197628762098], (-1747506197628762098,-1562433518295233873], (-1562433518295233873,-1510905361965029286], (-1510905361965029286,-955024327048105350], (-955024327048105350,-902476493306529612], (-902476493306529612,-769360745112648023], (-769360745112648023,-543541118886493788], (-543541118886493788,-304012802349790785], (-304012802349790785,-19111154256589931], (-19111154256589931,75668959209584463], (75668959209584463,396526505315049948], (396526505315049948,730287844325613580], (730287844325613580,764869696941825266], (764869696941825266,1009273555710939105], (1009273555710939105,1046463433627404849], (1046463433627404849,1156574345606742970], (1156574345606742970,1608206851987031093], (1608206851987031093,1854303260033171591], (1854303260033171591,2005529704335743884], (2005529704335743884,2105315455945877394], (2105315455945877394,2397350660946089317], (2397350660946089317,2506776172181420853], (2506776172181420853,2665486729324448146], (2665486729324448146,2950345160268109880], (2950345160268109880,3030334484419223440], (3030334484419223440,3196612566638089653], (3196612566638089653,3263950420281186972], (3263950420281186972,3564152689110379070], (3564152689110379070,3643632181840562222], (3643632181840562222,4008225340812712104], (4008225340812712104,4040989214129251410], (4040989214129251410,4041642270960322139], (4041642270960322139,4298251066956591339], (4298251066956591339,4724537568237720729], (4724537568237720729,4886018918451483897], (4886018918451483897,5155549049168388812], (5155549049168388812,5422266482664149350], (5422266482664149350,5481257444031834648], (5481257444031834648,5685847589112614179], (5685847589112614179,5822479798089329648], (5822479798089329648,6074739394812398612], (6074739394812398612,6326287148354067135], (6326287148354067135,6518308382899087639], (6518308382899087639,6552758060371867461], (6552758060371867461,6880036482779378206], (6880036482779378206,6944268180256267212], (6944268180256267212,7132115911741356829], (7132115911741356829,7397787764694099948], (7397787764694099948,7570609465114294476], (7570609465114294476,7609605493591299898], (7609605493591299898,8008609170029330609], (8008609170029330609,8122474797459510359], (8122474797459510359,8388281397726645271], (8388281397726645271,8415639169436526963], (8415639169436526963,8453982141082461656], (8453982141082461656,8949321254197623629]] for session 00000000-0000-0000-0000-000000000000 INFO [OptionalTasks:1] 2023-08-21 14:13:43,280 PaxosCleanupLocalCoordinator.java:185 - Completed 0 uncommitted paxos instances for reaper_db.running_repairs on ranges [(8949321254197623629,-9213432971660673857], (-9213432971660673857,-9192933261965959677], (-9192933261965959677,-8982706794757326805], (-8982706794757326805,-8832914117334669911], (-8832914117334669911,-8618130602700274606], (-8618130602700274606,-8552493702724506721], (-8552493702724506721,-8246791102046433164], (-8246791102046433164,-8170782611032428675], (-8170782611032428675,-8137677090435094317], (-8137677090435094317,-7934512670822306643], (-7934512670822306643,-7480993086384473908], (-7480993086384473908,-7401761397724200676], (-7401761397724200676,-7167418294598831506], (-7167418294598831506,-7108430211362077135], (-7108430211362077135,-6870171681049243246], (-6870171681049243246,-6741066273187288577], (-6741066273187288577,-6463141681642046892], (-6463141681642046892,-6322388590276599019], (-6322388590276599019,-5970303671972182143], (-5970303671972182143,-5923898288918239532], (-5923898288918239532,-5645469749029696098], (-5645469749029696098,-5572111350008274197], (-5572111350008274197,-5078868584596007045], (-5078868584596007045,-5050167380069296847], (-5050167380069296847,-4956534045839704033], (-4956534045839704033,-4569713867804116558], (-4569713867804116558,-4522987549679083109], (-4522987549679083109,-4138387943017099459], (-4138387943017099459,-4111504341517471547], (-4111504341517471547,-3833798175093222917], (-3833798175093222917,-3587074376887567689], (-3587074376887567689,-3424092478619438466], (-3424092478619438466,-3366529493325805395], (-3366529493325805395,-3173103050556310818], (-3173103050556310818,-3171436717315927809], (-3171436717315927809,-2754425367645621260], (-2754425367645621260,-2521499789003572909], (-2521499789003572909,-2306854027747740872], (-2306854027747740872,-2004148127377296438], (-2004148127377296438,-1959756370643946664], (-1959756370643946664,-1747506197628762098], (-1747506197628762098,-1562433518295233873], (-1562433518295233873,-1510905361965029286], (-1510905361965029286,-955024327048105350], (-955024327048105350,-902476493306529612], (-902476493306529612,-769360745112648023], (-769360745112648023,-543541118886493788], (-543541118886493788,-304012802349790785], (-304012802349790785,-19111154256589931], (-19111154256589931,75668959209584463], (75668959209584463,396526505315049948], (396526505315049948,730287844325613580], (730287844325613580,764869696941825266], (764869696941825266,1009273555710939105], (1009273555710939105,1046463433627404849], (1046463433627404849,1156574345606742970], (1156574345606742970,1608206851987031093], (1608206851987031093,1854303260033171591], (1854303260033171591,2005529704335743884], (2005529704335743884,2105315455945877394], (2105315455945877394,2397350660946089317], (2397350660946089317,2506776172181420853], (2506776172181420853,2665486729324448146], (2665486729324448146,2950345160268109880], (2950345160268109880,3030334484419223440], (3030334484419223440,3196612566638089653], (3196612566638089653,3263950420281186972], (3263950420281186972,3564152689110379070], (3564152689110379070,3643632181840562222], (3643632181840562222,4008225340812712104], (4008225340812712104,4040989214129251410], (4040989214129251410,4041642270960322139], (4041642270960322139,4298251066956591339], (4298251066956591339,4724537568237720729], (4724537568237720729,4886018918451483897], (4886018918451483897,5155549049168388812], (5155549049168388812,5422266482664149350], (5422266482664149350,5481257444031834648], (5481257444031834648,5685847589112614179], (5685847589112614179,5822479798089329648], (5822479798089329648,6074739394812398612], (6074739394812398612,6326287148354067135], (6326287148354067135,6518308382899087639], (6518308382899087639,6552758060371867461], (6552758060371867461,6880036482779378206], (6880036482779378206,6944268180256267212], (6944268180256267212,7132115911741356829], (7132115911741356829,7397787764694099948], (7397787764694099948,7570609465114294476], (7570609465114294476,7609605493591299898], (7609605493591299898,8008609170029330609], (8008609170029330609,8122474797459510359], (8122474797459510359,8388281397726645271], (8388281397726645271,8415639169436526963], (8415639169436526963,8453982141082461656], (8453982141082461656,8949321254197623629]] for session 00000000-0000-0000-0000-000000000000 INFO [ScheduledTasks:1] 2023-08-21 14:18:43,277 UncommittedTableData.java:567 - Scheduling uncommitted paxos data merge task for reaper_db.running_repairs INFO [OptionalTasks:1] 2023-08-21 14:18:43,280 PaxosCleanupLocalCoordinator.java:89 - Completing uncommitted paxos instances for reaper_db.running_repairs on ranges [(8949321254197623629,-9213432971660673857], (-9213432971660673857,-9192933261965959677], (-9192933261965959677,-8982706794757326805], (-8982706794757326805,-8832914117334669911], (-8832914117334669911,-8618130602700274606], (-8618130602700274606,-8552493702724506721], (-8552493702724506721,-8246791102046433164], (-8246791102046433164,-8170782611032428675], (-8170782611032428675,-8137677090435094317], (-8137677090435094317,-7934512670822306643], (-7934512670822306643,-7480993086384473908], (-7480993086384473908,-7401761397724200676], (-7401761397724200676,-7167418294598831506], (-7167418294598831506,-7108430211362077135], (-7108430211362077135,-6870171681049243246], (-6870171681049243246,-6741066273187288577], (-6741066273187288577,-6463141681642046892], (-6463141681642046892,-6322388590276599019], (-6322388590276599019,-5970303671972182143], (-5970303671972182143,-5923898288918239532], (-5923898288918239532,-5645469749029696098], (-5645469749029696098,-5572111350008274197], (-5572111350008274197,-5078868584596007045], (-5078868584596007045,-5050167380069296847], (-5050167380069296847,-4956534045839704033], (-4956534045839704033,-4569713867804116558], (-4569713867804116558,-4522987549679083109], (-4522987549679083109,-4138387943017099459], (-4138387943017099459,-4111504341517471547], (-4111504341517471547,-3833798175093222917], (-3833798175093222917,-3587074376887567689], (-3587074376887567689,-3424092478619438466], (-3424092478619438466,-3366529493325805395], (-3366529493325805395,-3173103050556310818], (-3173103050556310818,-3171436717315927809], (-3171436717315927809,-2754425367645621260], (-2754425367645621260,-2521499789003572909], (-2521499789003572909,-2306854027747740872], (-2306854027747740872,-2004148127377296438], (-2004148127377296438,-1959756370643946664], (-1959756370643946664,-1747506197628762098], (-1747506197628762098,-1562433518295233873], (-1562433518295233873,-1510905361965029286], (-1510905361965029286,-955024327048105350], (-955024327048105350,-902476493306529612], (-902476493306529612,-769360745112648023], (-769360745112648023,-543541118886493788], (-543541118886493788,-304012802349790785], (-304012802349790785,-19111154256589931], (-19111154256589931,75668959209584463], (75668959209584463,396526505315049948], (396526505315049948,730287844325613580], (730287844325613580,764869696941825266], (764869696941825266,1009273555710939105], (1009273555710939105,1046463433627404849], (1046463433627404849,1156574345606742970], (1156574345606742970,1608206851987031093], (1608206851987031093,1854303260033171591], (1854303260033171591,2005529704335743884], (2005529704335743884,2105315455945877394], (2105315455945877394,2397350660946089317], (2397350660946089317,2506776172181420853], (2506776172181420853,2665486729324448146], (2665486729324448146,2950345160268109880], (2950345160268109880,3030334484419223440], (3030334484419223440,3196612566638089653], (3196612566638089653,3263950420281186972], (3263950420281186972,3564152689110379070], (3564152689110379070,3643632181840562222], (3643632181840562222,4008225340812712104], (4008225340812712104,4040989214129251410], (4040989214129251410,4041642270960322139], (4041642270960322139,4298251066956591339], (4298251066956591339,4724537568237720729], (4724537568237720729,4886018918451483897], (4886018918451483897,5155549049168388812], (5155549049168388812,5422266482664149350], (5422266482664149350,5481257444031834648], (5481257444031834648,5685847589112614179], (5685847589112614179,5822479798089329648], (5822479798089329648,6074739394812398612], (6074739394812398612,6326287148354067135], (6326287148354067135,6518308382899087639], (6518308382899087639,6552758060371867461], (6552758060371867461,6880036482779378206], (6880036482779378206,6944268180256267212], (6944268180256267212,7132115911741356829], (7132115911741356829,7397787764694099948], (7397787764694099948,7570609465114294476], (7570609465114294476,7609605493591299898], (7609605493591299898,8008609170029330609], (8008609170029330609,8122474797459510359], (8122474797459510359,8388281397726645271], (8388281397726645271,8415639169436526963], (8415639169436526963,8453982141082461656], (8453982141082461656,8949321254197623629]] for session 00000000-0000-0000-0000-000000000000 INFO [OptionalTasks:1] 2023-08-21 14:18:43,280 PaxosCleanupLocalCoordinator.java:185 - Completed 0 uncommitted paxos instances for reaper_db.running_repairs on ranges [(8949321254197623629,-9213432971660673857], (-9213432971660673857,-9192933261965959677], (-9192933261965959677,-8982706794757326805], (-8982706794757326805,-8832914117334669911], (-8832914117334669911,-8618130602700274606], (-8618130602700274606,-8552493702724506721], (-8552493702724506721,-8246791102046433164], (-8246791102046433164,-8170782611032428675], (-8170782611032428675,-8137677090435094317], (-8137677090435094317,-7934512670822306643], (-7934512670822306643,-7480993086384473908], (-7480993086384473908,-7401761397724200676], (-7401761397724200676,-7167418294598831506], (-7167418294598831506,-7108430211362077135], (-7108430211362077135,-6870171681049243246], (-6870171681049243246,-6741066273187288577], (-6741066273187288577,-6463141681642046892], (-6463141681642046892,-6322388590276599019], (-6322388590276599019,-5970303671972182143], (-5970303671972182143,-5923898288918239532], (-5923898288918239532,-5645469749029696098], (-5645469749029696098,-5572111350008274197], (-5572111350008274197,-5078868584596007045], (-5078868584596007045,-5050167380069296847], (-5050167380069296847,-4956534045839704033], (-4956534045839704033,-4569713867804116558], (-4569713867804116558,-4522987549679083109], (-4522987549679083109,-4138387943017099459], (-4138387943017099459,-4111504341517471547], (-4111504341517471547,-3833798175093222917], (-3833798175093222917,-3587074376887567689], (-3587074376887567689,-3424092478619438466], (-3424092478619438466,-3366529493325805395], (-3366529493325805395,-3173103050556310818], (-3173103050556310818,-3171436717315927809], (-3171436717315927809,-2754425367645621260], (-2754425367645621260,-2521499789003572909], (-2521499789003572909,-2306854027747740872], (-2306854027747740872,-2004148127377296438], (-2004148127377296438,-1959756370643946664], (-1959756370643946664,-1747506197628762098], (-1747506197628762098,-1562433518295233873], (-1562433518295233873,-1510905361965029286], (-1510905361965029286,-955024327048105350], (-955024327048105350,-902476493306529612], (-902476493306529612,-769360745112648023], (-769360745112648023,-543541118886493788], (-543541118886493788,-304012802349790785], (-304012802349790785,-19111154256589931], (-19111154256589931,75668959209584463], (75668959209584463,396526505315049948], (396526505315049948,730287844325613580], (730287844325613580,764869696941825266], (764869696941825266,1009273555710939105], (1009273555710939105,1046463433627404849], (1046463433627404849,1156574345606742970], (1156574345606742970,1608206851987031093], (1608206851987031093,1854303260033171591], (1854303260033171591,2005529704335743884], (2005529704335743884,2105315455945877394], (2105315455945877394,2397350660946089317], (2397350660946089317,2506776172181420853], (2506776172181420853,2665486729324448146], (2665486729324448146,2950345160268109880], (2950345160268109880,3030334484419223440], (3030334484419223440,3196612566638089653], (3196612566638089653,3263950420281186972], (3263950420281186972,3564152689110379070], (3564152689110379070,3643632181840562222], (3643632181840562222,4008225340812712104], (4008225340812712104,4040989214129251410], (4040989214129251410,4041642270960322139], (4041642270960322139,4298251066956591339], (4298251066956591339,4724537568237720729], (4724537568237720729,4886018918451483897], (4886018918451483897,5155549049168388812], (5155549049168388812,5422266482664149350], (5422266482664149350,5481257444031834648], (5481257444031834648,5685847589112614179], (5685847589112614179,5822479798089329648], (5822479798089329648,6074739394812398612], (6074739394812398612,6326287148354067135], (6326287148354067135,6518308382899087639], (6518308382899087639,6552758060371867461], (6552758060371867461,6880036482779378206], (6880036482779378206,6944268180256267212], (6944268180256267212,7132115911741356829], (7132115911741356829,7397787764694099948], (7397787764694099948,7570609465114294476], (7570609465114294476,7609605493591299898], (7609605493591299898,8008609170029330609], (8008609170029330609,8122474797459510359], (8122474797459510359,8388281397726645271], (8388281397726645271,8415639169436526963], (8415639169436526963,8453982141082461656], (8453982141082461656,8949321254197623629]] for session 00000000-0000-0000-0000-000000000000 INFO [Native-Transport-Requests-91] 2023-08-21 14:19:46,699 NoSpamLogger.java:105 - Maximum memory usage reached (10.000GiB) for chunk-cache buffer pool, cannot allocate chunk of 8.000MiB INFO [Messaging-EventLoop-3-5] 2023-08-21 14:22:01,248 OutboundConnection.java:1153 - /10.142.0.17:7000(/10.142.0.17:53838)->/10.142.0.16:7000-LARGE_MESSAGES-84853394 successfully connected, version = 12, framing = LZ4, encryption = unencrypted INFO [ScheduledTasks:1] 2023-08-21 14:23:43,277 UncommittedTableData.java:567 - Scheduling uncommitted paxos data merge task for reaper_db.running_repairs INFO [OptionalTasks:1] 2023-08-21 14:23:43,281 PaxosCleanupLocalCoordinator.java:89 - Completing uncommitted paxos instances for reaper_db.running_repairs on ranges [(8949321254197623629,-9213432971660673857], (-9213432971660673857,-9192933261965959677], (-9192933261965959677,-8982706794757326805], (-8982706794757326805,-8832914117334669911], (-8832914117334669911,-8618130602700274606], (-8618130602700274606,-8552493702724506721], (-8552493702724506721,-8246791102046433164], (-8246791102046433164,-8170782611032428675], (-8170782611032428675,-8137677090435094317], (-8137677090435094317,-7934512670822306643], (-7934512670822306643,-7480993086384473908], (-7480993086384473908,-7401761397724200676], (-7401761397724200676,-7167418294598831506], (-7167418294598831506,-7108430211362077135], (-7108430211362077135,-6870171681049243246], (-6870171681049243246,-6741066273187288577], (-6741066273187288577,-6463141681642046892], (-6463141681642046892,-6322388590276599019], (-6322388590276599019,-5970303671972182143], (-5970303671972182143,-5923898288918239532], (-5923898288918239532,-5645469749029696098], (-5645469749029696098,-5572111350008274197], (-5572111350008274197,-5078868584596007045], (-5078868584596007045,-5050167380069296847], (-5050167380069296847,-4956534045839704033], (-4956534045839704033,-4569713867804116558], (-4569713867804116558,-4522987549679083109], (-4522987549679083109,-4138387943017099459], (-4138387943017099459,-4111504341517471547], (-4111504341517471547,-3833798175093222917], (-3833798175093222917,-3587074376887567689], (-3587074376887567689,-3424092478619438466], (-3424092478619438466,-3366529493325805395], (-3366529493325805395,-3173103050556310818], (-3173103050556310818,-3171436717315927809], (-3171436717315927809,-2754425367645621260], (-2754425367645621260,-2521499789003572909], (-2521499789003572909,-2306854027747740872], (-2306854027747740872,-2004148127377296438], (-2004148127377296438,-1959756370643946664], (-1959756370643946664,-1747506197628762098], (-1747506197628762098,-1562433518295233873], (-1562433518295233873,-1510905361965029286], (-1510905361965029286,-955024327048105350], (-955024327048105350,-902476493306529612], (-902476493306529612,-769360745112648023], (-769360745112648023,-543541118886493788], (-543541118886493788,-304012802349790785], (-304012802349790785,-19111154256589931], (-19111154256589931,75668959209584463], (75668959209584463,396526505315049948], (396526505315049948,730287844325613580], (730287844325613580,764869696941825266], (764869696941825266,1009273555710939105], (1009273555710939105,1046463433627404849], (1046463433627404849,1156574345606742970], (1156574345606742970,1608206851987031093], (1608206851987031093,1854303260033171591], (1854303260033171591,2005529704335743884], (2005529704335743884,2105315455945877394], (2105315455945877394,2397350660946089317], (2397350660946089317,2506776172181420853], (2506776172181420853,2665486729324448146], (2665486729324448146,2950345160268109880], (2950345160268109880,3030334484419223440], (3030334484419223440,3196612566638089653], (3196612566638089653,3263950420281186972], (3263950420281186972,3564152689110379070], (3564152689110379070,3643632181840562222], (3643632181840562222,4008225340812712104], (4008225340812712104,4040989214129251410], (4040989214129251410,4041642270960322139], (4041642270960322139,4298251066956591339], (4298251066956591339,4724537568237720729], (4724537568237720729,4886018918451483897], (4886018918451483897,5155549049168388812], (5155549049168388812,5422266482664149350], (5422266482664149350,5481257444031834648], (5481257444031834648,5685847589112614179], (5685847589112614179,5822479798089329648], (5822479798089329648,6074739394812398612], (6074739394812398612,6326287148354067135], (6326287148354067135,6518308382899087639], (6518308382899087639,6552758060371867461], (6552758060371867461,6880036482779378206], (6880036482779378206,6944268180256267212], (6944268180256267212,7132115911741356829], (7132115911741356829,7397787764694099948], (7397787764694099948,7570609465114294476], (7570609465114294476,7609605493591299898], (7609605493591299898,8008609170029330609], (8008609170029330609,8122474797459510359], (8122474797459510359,8388281397726645271], (8388281397726645271,8415639169436526963], (8415639169436526963,8453982141082461656], (8453982141082461656,8949321254197623629]] for session 00000000-0000-0000-0000-000000000000 INFO [OptionalTasks:1] 2023-08-21 14:23:43,281 PaxosCleanupLocalCoordinator.java:185 - Completed 0 uncommitted paxos instances for reaper_db.running_repairs on ranges [(8949321254197623629,-9213432971660673857], (-9213432971660673857,-9192933261965959677], (-9192933261965959677,-8982706794757326805], (-8982706794757326805,-8832914117334669911], (-8832914117334669911,-8618130602700274606], (-8618130602700274606,-8552493702724506721], (-8552493702724506721,-8246791102046433164], (-8246791102046433164,-8170782611032428675], (-8170782611032428675,-8137677090435094317], (-8137677090435094317,-7934512670822306643], (-7934512670822306643,-7480993086384473908], (-7480993086384473908,-7401761397724200676], (-7401761397724200676,-7167418294598831506], (-7167418294598831506,-7108430211362077135], (-7108430211362077135,-6870171681049243246], (-6870171681049243246,-6741066273187288577], (-6741066273187288577,-6463141681642046892], (-6463141681642046892,-6322388590276599019], (-6322388590276599019,-5970303671972182143], (-5970303671972182143,-5923898288918239532], (-5923898288918239532,-5645469749029696098], (-5645469749029696098,-5572111350008274197], (-5572111350008274197,-5078868584596007045], (-5078868584596007045,-5050167380069296847], (-5050167380069296847,-4956534045839704033], (-4956534045839704033,-4569713867804116558], (-4569713867804116558,-4522987549679083109], (-4522987549679083109,-4138387943017099459], (-4138387943017099459,-4111504341517471547], (-4111504341517471547,-3833798175093222917], (-3833798175093222917,-3587074376887567689], (-3587074376887567689,-3424092478619438466], (-3424092478619438466,-3366529493325805395], (-3366529493325805395,-3173103050556310818], (-3173103050556310818,-3171436717315927809], (-3171436717315927809,-2754425367645621260], (-2754425367645621260,-2521499789003572909], (-2521499789003572909,-2306854027747740872], (-2306854027747740872,-2004148127377296438], (-2004148127377296438,-1959756370643946664], (-1959756370643946664,-1747506197628762098], (-1747506197628762098,-1562433518295233873], (-1562433518295233873,-1510905361965029286], (-1510905361965029286,-955024327048105350], (-955024327048105350,-902476493306529612], (-902476493306529612,-769360745112648023], (-769360745112648023,-543541118886493788], (-543541118886493788,-304012802349790785], (-304012802349790785,-19111154256589931], (-19111154256589931,75668959209584463], (75668959209584463,396526505315049948], (396526505315049948,730287844325613580], (730287844325613580,764869696941825266], (764869696941825266,1009273555710939105], (1009273555710939105,1046463433627404849], (1046463433627404849,1156574345606742970], (1156574345606742970,1608206851987031093], (1608206851987031093,1854303260033171591], (1854303260033171591,2005529704335743884], (2005529704335743884,2105315455945877394], (2105315455945877394,2397350660946089317], (2397350660946089317,2506776172181420853], (2506776172181420853,2665486729324448146], (2665486729324448146,2950345160268109880], (2950345160268109880,3030334484419223440], (3030334484419223440,3196612566638089653], (3196612566638089653,3263950420281186972], (3263950420281186972,3564152689110379070], (3564152689110379070,3643632181840562222], (3643632181840562222,4008225340812712104], (4008225340812712104,4040989214129251410], (4040989214129251410,4041642270960322139], (4041642270960322139,4298251066956591339], (4298251066956591339,4724537568237720729], (4724537568237720729,4886018918451483897], (4886018918451483897,5155549049168388812], (5155549049168388812,5422266482664149350], (5422266482664149350,5481257444031834648], (5481257444031834648,5685847589112614179], (5685847589112614179,5822479798089329648], (5822479798089329648,6074739394812398612], (6074739394812398612,6326287148354067135], (6326287148354067135,6518308382899087639], (6518308382899087639,6552758060371867461], (6552758060371867461,6880036482779378206], (6880036482779378206,6944268180256267212], (6944268180256267212,7132115911741356829], (7132115911741356829,7397787764694099948], (7397787764694099948,7570609465114294476], (7570609465114294476,7609605493591299898], (7609605493591299898,8008609170029330609], (8008609170029330609,8122474797459510359], (8122474797459510359,8388281397726645271], (8388281397726645271,8415639169436526963], (8415639169436526963,8453982141082461656], (8453982141082461656,8949321254197623629]] for session 00000000-0000-0000-0000-000000000000 INFO [MutationStage-1] 2023-08-21 14:27:32,984 ColumnFamilyStore.java:2594 - Truncating reaper_db.running_repairs INFO [MutationStage-1] 2023-08-21 14:27:32,985 ColumnFamilyStore.java:1012 - Enqueuing flush of reaper_db.running_repairs, Reason: TRUNCATE, Usage: 4.832KiB (0%) on-heap, 9.018MiB (0%) off-heap INFO [PerDiskMemtableFlushWriter_0:336] 2023-08-21 14:27:32,998 Flushing.java:145 - Writing Memtable-running_repairs@981907744(1.906KiB serialized bytes, 96588 ops, 4.832KiB (0%) on-heap, 9.018MiB (0%) off-heap), flushed range = [min(-9223372036854775808), max(9223372036854775807)) INFO [PerDiskMemtableFlushWriter_0:336] 2023-08-21 14:27:32,999 Flushing.java:171 - Completed flushing /cassandra/data/reaper_db/running_repairs-3c927320f31b11ec95088d543664f0c0/nb-1-big-Data.db (1.129KiB) for commitlog position CommitLogPosition(segmentId=1692302267488, position=2412018) INFO [MutationStage-1] 2023-08-21 14:27:33,036 ColumnFamilyStore.java:2628 - Truncating reaper_db.running_repairs with truncatedAt=1692628053035 INFO [MutationStage-1] 2023-08-21 14:27:33,042 ColumnFamilyStore.java:3095 - Truncation is dropping 1 sstables and keeping 0 due to sstable.maxDataAge > truncatedAt INFO [MutationStage-1] 2023-08-21 14:27:33,062 ColumnFamilyStore.java:1012 - Enqueuing flush of system.local, Reason: INTERNALLY_FORCED, Usage: 0.396KiB (0%) on-heap, 0.072KiB (0%) off-heap INFO [PerDiskMemtableFlushWriter_0:337] 2023-08-21 14:27:33,072 Flushing.java:145 - Writing Memtable-local@1226281778(0.091KiB serialized bytes, 1 ops, 0.396KiB (0%) on-heap, 0.072KiB (0%) off-heap), flushed range = [min(-9223372036854775808), max(9223372036854775807)) INFO [PerDiskMemtableFlushWriter_0:337] 2023-08-21 14:27:33,072 Flushing.java:171 - Completed flushing /cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nb-523-big-Data.db (0.063KiB) for commitlog position CommitLogPosition(segmentId=1692302267488, position=2412121) INFO [MutationStage-1] 2023-08-21 14:27:33,320 ColumnFamilyStore.java:2655 - Truncate of reaper_db.running_repairs is complete INFO [NonPeriodicTasks:1] 2023-08-21 14:27:33,923 SSTable.java:127 - Deleting sstable: /cassandra/data/reaper_db/running_repairs-3c927320f31b11ec95088d543664f0c0/nb-1-big INFO [MutationStage-1] 2023-08-21 14:28:08,568 ColumnFamilyStore.java:2594 - Truncating system.paxos INFO [MutationStage-1] 2023-08-21 14:28:08,571 ColumnFamilyStore.java:2628 - Truncating system.paxos with truncatedAt=1692628088569 INFO [MutationStage-1] 2023-08-21 14:28:08,574 PaxosUncommittedTracker.java:223 - truncating paxos uncommitted info INFO [MutationStage-1] 2023-08-21 14:28:08,574 UncommittedTableData.java:589 - truncating uncommitting paxos date for reaper_db.running_repairs INFO [MutationStage-1] 2023-08-21 14:28:08,575 ColumnFamilyStore.java:1012 - Enqueuing flush of system.local, Reason: INTERNALLY_FORCED, Usage: 0.396KiB (0%) on-heap, 0.072KiB (0%) off-heap INFO [PerDiskMemtableFlushWriter_0:336] 2023-08-21 14:28:08,583 Flushing.java:145 - Writing Memtable-local@876691456(0.091KiB serialized bytes, 1 ops, 0.396KiB (0%) on-heap, 0.072KiB (0%) off-heap), flushed range = [min(-9223372036854775808), max(9223372036854775807)) INFO [PerDiskMemtableFlushWriter_0:336] 2023-08-21 14:28:08,584 Flushing.java:171 - Completed flushing /cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nb-524-big-Data.db (0.063KiB) for commitlog position CommitLogPosition(segmentId=1692302267488, position=2442859) INFO [MutationStage-1] 2023-08-21 14:28:08,730 ColumnFamilyStore.java:2655 - Truncate of system.paxos is complete INFO [Native-Transport-Requests-87] 2023-08-21 14:35:37,894 NoSpamLogger.java:105 - Maximum memory usage reached (10.000GiB) for chunk-cache buffer pool, cannot allocate chunk of 8.000MiB

[adejanovski]

Hi @alextechnology,

Reaper uses LWTs on the reaper_db.running_repairs table to orchestrate segment execution. From what I can see in the Cassandra code, these messages are part of the natural execution of LWTs, and as verbose as they are, they're info level. I don't see the cleanup process failing, but rather not finding anything to cleanup (which seems to be fine).

A few questions:

• Do you see any performance impact on Cassandra when these messages show up?
• Do you see repairs making progress as they should?
• Did you recently update Cassandra to a newer version?

[alextechnology]

Hi @alextechnology,

Reaper uses LWTs on the reaper_db.running_repairs table to orchestrate segment execution. From what I can see in the Cassandra code, these messages are part of the natural execution of LWTs, and as verbose as they are, they're info level. I don't see the cleanup process failing, but rather not finding anything to cleanup (which seems to be fine).

A few questions:

• Do you see any performance impact on Cassandra when these messages show up?
• Do you see repairs making progress as they should?
• Did you recently update Cassandra to a newer version?

Hi @adejanovski,

Thanks to looking into this. To answer your questions:

- Do you see any performance impact on Cassandra when these messages show up? The only issue that may be arising is that we noticed our long running Cassandra client processes running in flask appear to have a greater incidence of dropping connections if this goes unaddressed (ie. not doing the TRUNCATE TABLE commands I mentioned previously). It's hard to say for sure this effect is from the looping Paxos cleanup log issue or not, but we've rarely seen this happen before without some directly attributed cause (ie. backfilling large amounts of data into the cluster at high rate sometimes causes client sessions to timeout). However, this has happened on two separate, geographically separated VMs twice in a row which is why I made this post as that has never happened before without a directly attributable cause like a bulk backfill I mentioned

- Do you see repairs making progress as they should? Yep, repairs scheduled in reaper seem to be running fine and completing fine and doing so within the historical runtime, so I don't see any issues here.

- Did you recently update Cassandra to a newer version? We are using the packaged deployment of Cassandra via aptitude in Ubuntu Pro 20.04.6 and are currently running cassandra + cassandra-tools version 4.1.3

EDIT: I checked and looks like the last reaper aptitude upgrade we did was on July 20, 2023 from version 3.3.2 to 3.3.3. Additionally, I see the paxos log messages appearing from at least July 29, 2023 forward and starting every weekend with the Repear repair. Unfortunately, I don't have cassandra logs older than this but I can see this first weekend + subsequent week + following weekend had all the log messages appearing and it was only on the subsequent Monday that I discovered the cassandra client failures and started investigating this issue. Unfortunately, I can't say for sure when the log messages first started appearing but it was at least 1-2 weeks before issues arose that prompted me to investigate. Additionally I see Cassandra upgrades on 2023-07-11 (4.0.5 -> 4.1.2) and 2023-07-26 (4.1.2 -> 4.1.3) but both of these are prior to the earliest cassandra logs I have

Our scheduled repairs run on the weekend and I can see the same log messages are repeating. Unfortunately, this is a production system otherwise I'd let it go without the TRUNCATE TABLES action to see if it causes the Flask based cassandra client instances to time out as previously this happened on Tuesday and Wednesday. I also don't see any excessive load or obvious performance issues using the cassandra cluster. But I'm always weary of this kind of unintentional repeated routine running without conclusion. There's no actual data system.paxos or reaper_db.running_repairs when selecting, though the latter does have some nodetool stats which I imagine is from the weekend repairs (see below nodetool outputs). I'm wondering if perhaps this is a Cassandra issue since it's failing to complete, perhaps because of a bad codepath as there's no data to cleanup and the TRUNCATE TABLE statement somehow breaks the loop of attempting to repair.

I'll liklely just schedule a Monday task to run the TRUNCATE TABLE until I figure out what's going on. Regardless, I really appreciate you looking into this and the Reaper tool in general so thanks for your amazing work!

REDACTED@REDACTED:~$ nodetool tablestats system.paxos
Total number of tables: 87
----------------
Keyspace : system
        Read Count: 2352
        Read Latency: 0.27190008503401364 ms
        Write Count: 1464387
        Write Latency: 0.023430907266999774 ms
        Pending Flushes: 0
                Table: paxos
                SSTable count: 0
                Old SSTable count: 0
                SSTables in each level: [0, 0, 0, 0, 0, 0, 0, 0, 0]
                SSTable bytes in each level: [0, 0, 0, 0, 0, 0, 0, 0, 0]
                Space used (live): 0
                Space used (total): 0
                Space used by snapshots (total): 0
                Off heap memory used (total): 0
                SSTable Compression Ratio: -1.0
                Number of partitions (estimate): 0
                Memtable cell count: 0
                Memtable data size: 0
                Memtable off heap memory used: 0
                Memtable switch count: 25
                Local read count: 8
                Local read latency: NaN ms
                Local write count: 129195
                Local write latency: NaN ms
                Pending flushes: 0
                Percent repaired: 100.0
                Bytes repaired: 0.000KiB
                Bytes unrepaired: 0.000KiB
                Bytes pending repair: 0.000KiB
                Bloom filter false positives: 0
                Bloom filter false ratio: 0.00000
                Bloom filter space used: 0
                Bloom filter off heap memory used: 0
                Index summary off heap memory used: 0
                Compression metadata off heap memory used: 0
                Compacted partition minimum bytes: 0
                Compacted partition maximum bytes: 0
                Compacted partition mean bytes: 0
                Average live cells per slice (last five minutes): NaN
                Maximum live cells per slice (last five minutes): 0
                Average tombstones per slice (last five minutes): NaN
                Maximum tombstones per slice (last five minutes): 0
                Dropped Mutations: 0
                Droppable tombstone ratio: 0.00000

----------------
REDACTED@REDACTED:~$ nodetool tablestats reaper_db.running_repairs;
Total number of tables: 87
----------------
Keyspace : reaper_db
        Read Count: 1085795
        Read Latency: 1.2001242361587592 ms
        Write Count: 206682
        Write Latency: 0.054893449840818266 ms
        Pending Flushes: 0
                Table: running_repairs
                SSTable count: 0
                Old SSTable count: 0
                SSTables in each level: [0, 0, 0, 0, 0, 0, 0, 0, 0]
                SSTable bytes in each level: [0, 0, 0, 0, 0, 0, 0, 0, 0]
                Space used (live): 0
                Space used (total): 0
                Space used by snapshots (total): 16587
                Off heap memory used (total): 9554486
                SSTable Compression Ratio: -1.0
                Number of partitions (estimate): 3
                Memtable cell count: 98946
                Memtable data size: 1952
                Memtable off heap memory used: 9554486
                Memtable switch count: 1
                Local read count: 178374
                Local read latency: NaN ms
                Local write count: 32665
                Local write latency: NaN ms
                Pending flushes: 0
                Percent repaired: 100.0
                Bytes repaired: 0.000KiB
                Bytes unrepaired: 0.000KiB
                Bytes pending repair: 0.000KiB
                Bloom filter false positives: 0
                Bloom filter false ratio: 0.00000
                Bloom filter space used: 0
                Bloom filter off heap memory used: 0
                Index summary off heap memory used: 0
                Compression metadata off heap memory used: 0
                Compacted partition minimum bytes: 0
                Compacted partition maximum bytes: 0
                Compacted partition mean bytes: 0
                Average live cells per slice (last five minutes): NaN
                Maximum live cells per slice (last five minutes): 0
                Average tombstones per slice (last five minutes): NaN
                Maximum tombstones per slice (last five minutes): 0
                Dropped Mutations: 0
                Droppable tombstone ratio: 0.00000

----------------

[alextechnology]

Just a quick follow up - after this weekend, I see the same repeat logs for cleaning up paxos uncommitted transactions on reaper_db.running repairs AND reaper_db.leader. This is the first time I've seen this happening for reaper_db.leader though nothing on the schedule side has changed and the weekend repair jobs appear to have completed successfully without issue

[adejanovski]

Hi @alextechnology, this local cleanup for Paxos has been introduced in 4.1, it didn't exist in 4.0. So I would say it's just a new behavior that landed in this minor, which Reaper has no control over. If I were you I'd create a ticket in the Cassandra Jira with all your observations, or start by asking on the mailing list.

Again, this cleanup seems to happen for every LWT (and we use them for scheduling segments), and the fact that it's mentioning that the cleanup affect "0" paxos instance would indicate that things are going well (no leftover paxos transaction).

[alextechnology]

@adejanovski Thanks for this - I'm going to close this issue as it's clearly a Cassandra problem and see about getting it reported there