test: debugging output to help diagnose ar_reject_chunks_tests failures

.github/workflows/test.yml

@@ -169,6 +169,7 @@ jobs:
         core_test_mod: [
             ## Long-running tests. Put these first to limit the overall runtime of the
             ## test suite
+            ar_reject_chunks_tests,
             ar_coordinated_mining_tests,
             ar_data_sync_recovers_from_corruption_test,
             ar_data_sync_syncs_data_test,
@@ -182,8 +183,7 @@ jobs:
             ar_packing_tests,
             ar_poa,
             ar_vdf_server_tests,
-            ar_post_block_tests,
-            ar_reject_chunks_tests
+            ar_post_block_tests
           ]
     steps:
       - uses: actions/checkout@v4

apps/arweave/src/ar_data_sync.erl

@@ -132,7 +132,9 @@ add_chunk_to_disk_pool(DataRoot, DataPath, Chunk, Offset, TXSize) ->
 		case {DataRootOffsetReply, DataRootInDiskPool} of
 			{not_found, []} ->
 				?LOG_WARNING([{event, failed_to_add_chunk_to_disk_pool},
-					{reason, data_root_not_found}, {offset, Offset}]),
+					{reason, data_root_not_found}, {offset, Offset}, {chunk_size, ChunkSize},
+					{data_root, ar_util:encode(DataRoot)},
+					{data_root_key, ar_util:encode(DataRootKey)}]),
 				{error, data_root_not_found};
 			{not_found, [{_, {Size, Timestamp, TXIDSet}}]} ->
 				case Size + ChunkSize > DataRootLimit
@@ -382,6 +384,8 @@ maybe_drop_data_root_from_disk_pool(_, 0, _) ->
 maybe_drop_data_root_from_disk_pool(DataRoot, _, _) when byte_size(DataRoot) < 32 ->
 	ok;
 maybe_drop_data_root_from_disk_pool(DataRoot, TXSize, TXID) ->
+	?LOG_DEBUG([{event, maybe_drop_data_root_from_disk_pool}, {data_root, ar_util:encode(DataRoot)},
+			{tx_size, TXSize}, {tx_id, ar_util:encode(TXID)} ]),
 	Key = << DataRoot:32/binary, TXSize:?OFFSET_KEY_BITSIZE >>,
 	case ets:lookup(ar_disk_pool_data_roots, Key) of
 		[] ->
@@ -909,6 +913,7 @@ handle_cast({cut, Start}, #sync_data_state{ store_id = StoreID,
 	{noreply, State};
 
 handle_cast({add_tip_block, BlockTXPairs, BI}, State) ->
+	?LOG_DEBUG([{event, add_tip_block}]),
 	#sync_data_state{ store_id = StoreID, weave_size = CurrentWeaveSize,
 			block_index = CurrentBI } = State,
 	{BlockStartOffset, Blocks} = pick_missing_blocks(CurrentBI, BlockTXPairs),
@@ -2601,6 +2606,7 @@ update_tx_index(SizeTaggedTXs, BlockStartOffset, StoreID) ->
 add_block_data_roots([], _CurrentWeaveSize, _StoreID) ->
 	{ok, sets:new()};
 add_block_data_roots(SizeTaggedTXs, CurrentWeaveSize, StoreID) ->
+	?LOG_DEBUG([{event, add_block_data_roots}]),
 	SizeTaggedDataRoots = [{Root, Offset} || {{_, Root}, Offset} <- SizeTaggedTXs],
 	{TXRoot, TXTree} = ar_merkle:generate_tree(SizeTaggedDataRoots),
 	{BlockSize, DataRootIndexKeySet, Args} = lists:foldl(
@@ -2638,6 +2644,7 @@ add_block_data_roots(SizeTaggedTXs, CurrentWeaveSize, StoreID) ->
 	{ok, DataRootIndexKeySet}.
 
 update_data_root_index(DataRoot, TXSize, AbsoluteTXStartOffset, TXPath, StoreID) ->
+	?LOG_DEBUG([{event, update_data_root_index}, {data_root, ar_util:encode(DataRoot)}]),
 	ar_kv:put({data_root_index, StoreID},
 			data_root_key_v2(DataRoot, TXSize, AbsoluteTXStartOffset), TXPath).
 

apps/arweave/src/ar_mempool.erl

@@ -124,9 +124,13 @@ add_tx2(#tx{ id = TXID } = TX, Status) ->
 					%%    until the mempool is small enough
 					%% To limit revalidation work, all of these checks assume
 					%% every TX in the mempool has previously been validated.
+					?LOG_DEBUG([{event, drop_txs_clashing}]),
 					drop_txs(find_clashing_txs(TX)),
+					?LOG_DEBUG([{event, drop_txs_overspent}]),
 					drop_txs(find_overspent_txs(TX)),
-					drop_txs(find_low_priority_txs());
+					?LOG_DEBUG([{event, drop_txs_low_priority}]),
+					drop_txs(find_low_priority_txs()),
+					?LOG_DEBUG([{event, drop_txs_done}]);
 				false ->
 					noop
 			end
@@ -148,6 +152,8 @@ drop_txs(DroppedTXs) ->
 drop_txs([], _RemoveTXPrefixes, _DropFromDiskPool) ->
 	ok;
 drop_txs(DroppedTXs, RemoveTXPrefixes, DropFromDiskPool) ->
+	?LOG_DEBUG([{event, drop_txs}, {dropped_txs, length(DroppedTXs)}, {remove_tx_prefixes, RemoveTXPrefixes},
+			{drop_from_disk_pool, DropFromDiskPool}]),
 	prometheus_histogram:observe_duration(drop_txs_duration_milliseconds,
 		fun() ->
 			drop_txs2(DroppedTXs, RemoveTXPrefixes, DropFromDiskPool)

apps/arweave/src/ar_node_worker.erl

@@ -716,6 +716,8 @@ handle_task({filter_mempool, Mempool}, State) ->
 									valid ->
 										Acc;
 									{invalid, _Reason} ->
+										?LOG_DEBUG([{event, drop_txs_invalid_tx}, {tx_id, ar_util:encode(TX#tx.id)},
+												{reason, _Reason}]),
 										[TX | Acc]
 								end
 							end,
@@ -724,6 +726,7 @@ handle_task({filter_mempool, Mempool}, State) ->
 						)
 					end
 				),
+			?LOG_DEBUG([{event, drop_txs_invalid}, {invalid_txs, length(InvalidTXs)}]),
 			ar_mempool:drop_txs(InvalidTXs),
 			case RemainingMempool of
 				[] ->
@@ -1397,6 +1400,7 @@ apply_validated_block(State, B, PrevBlocks, Orphans, RecentBI, BlockTXPairs) ->
 	end.
 
 apply_validated_block2(State, B, PrevBlocks, Orphans, RecentBI, BlockTXPairs) ->
+	?LOG_DEBUG([{event, apply_validated_block2}]),
 	[{current, CurrentH}] = ets:lookup(node_state, current),
 	BH = B#block.indep_hash,
 	%% Overwrite the block to store computed size tagged txs - they
@@ -1445,7 +1449,9 @@ apply_validated_block2(State, B, PrevBlocks, Orphans, RecentBI, BlockTXPairs) ->
 	),
 	ar_disk_cache:write_block(B),
 	BlockTXs = B#block.txs,
+	?LOG_DEBUG([{event, apply_validated_block2_drop_txs}, {block_txs, length(BlockTXs)}]),
 	ar_mempool:drop_txs(BlockTXs, false, false),
+	?LOG_DEBUG([{event, apply_validated_block2_filter_mempool}]),
 	gen_server:cast(self(), {filter_mempool, ar_mempool:get_all_txids()}),
 	{BlockAnchors, RecentTXMap} = get_block_anchors_and_recent_txs_map(BlockTXPairs),
 	Height = B#block.height,
@@ -1461,6 +1467,7 @@ apply_validated_block2(State, B, PrevBlocks, Orphans, RecentBI, BlockTXPairs) ->
 	OrphanCount = length(Orphans),
 	ar_block_index:update(AddedBIElements, OrphanCount),
 	RecentBI2 = lists:sublist(RecentBI, ?BLOCK_INDEX_HEAD_LEN),
+	?LOG_DEBUG([{event, apply_validated_block2_add_tip_block}]),
 	ar_data_sync:add_tip_block(BlockTXPairs, RecentBI2),
 	ar_header_sync:add_tip_block(B, RecentBI2),
 	lists:foreach(