IGNITE-21418 Add more logs to debug this issue

[Cyrill]

https://issues.apache.org/jira/browse/IGNITE-21418

[sanpwc]

Could you please share an example of logs output?

[Cyrill]

This is how the output looks like:

[2024-05-29T10:32:43,686][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Primary node for accounts table is [node=itdttntr_n_20000]
[2024-05-29T10:32:43,687][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Cluster times:
[2024-05-29T10:32:43,687][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Client clock [time=HybridTimestamp [physical=2024-05-29 10:32:43:686 +0300, logical=1, composite=112523212468125697]]
[2024-05-29T10:32:43,687][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Cluster clock [node=itdttntr_n_20001, time=HybridTimestamp [physical=2024-05-29 10:32:43:678 +0300, logical=4, composite=112523212467601412]]
[2024-05-29T10:32:43,687][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Cluster clock [node=itdttntr_n_20002, time=HybridTimestamp [physical=2024-05-29 10:32:43:678 +0300, logical=5, composite=112523212467601413]]
[2024-05-29T10:32:43,688][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Cluster clock [node=itdttntr_n_20000, time=HybridTimestamp [physical=2024-05-29 10:32:43:688 +0300, logical=0, composite=112523212468256768]]

[2024-05-29T10:32:43,688][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Replica info:
[2024-05-29T10:32:43,689][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Partition data [node=itdttntr_n_20001, groupId=0_part_0, data={RowId [partitionId=0, uuid=af8c50c3-48f3-48b2-9785-bcbe481ce55c]=VersionChain [rowId=RowId [partitionId=0, uuid=af8c50c3-48f3-48b2-9785-bcbe481ce55c], row=org.apache.ignite.internal.schema.BinaryRowImpl@c9f591a9, ts=HybridTimestamp [physical=2024-05-29 10:32:43:555 +0300, logical=0, composite=112523212459540480], txId=null, commitTableId=null, commitPartitionId=-1], RowId [partitionId=0, uuid=b64eae79-3190-4e68-8b8a-c6e05c3d1d27]=VersionChain [rowId=RowId [partitionId=0, uuid=b64eae79-3190-4e68-8b8a-c6e05c3d1d27], row=org.apache.ignite.internal.schema.BinaryRowImpl@c9f60608, ts=HybridTimestamp [physical=2024-05-29 10:32:43:555 +0300, logical=0, composite=112523212459540480], txId=null, commitTableId=null, commitPartitionId=-1]}]
[2024-05-29T10:32:43,689][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Index data [node=itdttntr_n_20001, groupId=0_part_0, data={java.nio.HeapByteBuffer[pos=0 lim=3 cap=3]=[RowId [partitionId=0, uuid=b64eae79-3190-4e68-8b8a-c6e05c3d1d27]], java.nio.HeapByteBuffer[pos=0 lim=3 cap=3]=[RowId [partitionId=0, uuid=af8c50c3-48f3-48b2-9785-bcbe481ce55c]]}]
[2024-05-29T10:32:43,690][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Tx state data [node=itdttntr_n_20001, groupId=0_part_0, data=TestTxStateStorage [storage=ConcurrentSkipListMap {018fc343-fbd8-0000-ffff-ffff00000001=TxMeta [txState=COMMITTED, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:624 +0300, logical=0, composite=112523212464062464]]}, lastAppliedIndex=6, lastAppliedTerm=1, rebalanceFutureReference=null, closed=false]]
[2024-05-29T10:32:43,691][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Partition data [node=itdttntr_n_20001, groupId=2_part_0, data={}]
[2024-05-29T10:32:43,691][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Index data [node=itdttntr_n_20001, groupId=2_part_0, data={}]
[2024-05-29T10:32:43,692][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Tx state data [node=itdttntr_n_20001, groupId=2_part_0, data=TestTxStateStorage [storage=ConcurrentSkipListMap {018fc343-fbd8-0000-ffff-ffff00000001=TxMeta [txState=COMMITTED, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:624 +0300, logical=0, composite=112523212464062464]]}, lastAppliedIndex=6, lastAppliedTerm=1, rebalanceFutureReference=null, closed=false]]
[2024-05-29T10:32:43,693][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Volatile tx state data [node=itdttntr_n_20001, data={018fc343-fb5d-0000-ffff-ffff00000001=TxStateMeta [txState=COMMITTED, txCoordinatorId=a0b6c316-1a11-4bc6-a146-6f9ed6fb5d5e, commitPartitionId=null, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:555 +0300, logical=0, composite=112523212459540480], initialVacuumObservationTimestamp=null, cleanupCompletionTimestamp=null], 018fc343-fbd8-0000-ffff-ffff00000001=TxStateMeta [txState=COMMITTED, txCoordinatorId=null, commitPartitionId=0_part_0, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:624 +0300, logical=0, composite=112523212464062464], initialVacuumObservationTimestamp=null, cleanupCompletionTimestamp=null]}]

[2024-05-29T10:32:43,694][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Partition data [node=itdttntr_n_20002, groupId=0_part_0, data={RowId [partitionId=0, uuid=af8c50c3-48f3-48b2-9785-bcbe481ce55c]=VersionChain [rowId=RowId [partitionId=0, uuid=af8c50c3-48f3-48b2-9785-bcbe481ce55c], row=org.apache.ignite.internal.schema.BinaryRowImpl@c9f591a9, ts=HybridTimestamp [physical=2024-05-29 10:32:43:555 +0300, logical=0, composite=112523212459540480], txId=null, commitTableId=null, commitPartitionId=-1], RowId [partitionId=0, uuid=b64eae79-3190-4e68-8b8a-c6e05c3d1d27]=VersionChain [rowId=RowId [partitionId=0, uuid=b64eae79-3190-4e68-8b8a-c6e05c3d1d27], row=org.apache.ignite.internal.schema.BinaryRowImpl@c9f60608, ts=HybridTimestamp [physical=2024-05-29 10:32:43:555 +0300, logical=0, composite=112523212459540480], txId=null, commitTableId=null, commitPartitionId=-1]}]
[2024-05-29T10:32:43,694][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Index data [node=itdttntr_n_20002, groupId=0_part_0, data={java.nio.HeapByteBuffer[pos=0 lim=3 cap=3]=[RowId [partitionId=0, uuid=b64eae79-3190-4e68-8b8a-c6e05c3d1d27]], java.nio.HeapByteBuffer[pos=0 lim=3 cap=3]=[RowId [partitionId=0, uuid=af8c50c3-48f3-48b2-9785-bcbe481ce55c]]}]
[2024-05-29T10:32:43,694][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Tx state data [node=itdttntr_n_20002, groupId=0_part_0, data=TestTxStateStorage [storage=ConcurrentSkipListMap {018fc343-fbd8-0000-ffff-ffff00000001=TxMeta [txState=COMMITTED, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:624 +0300, logical=0, composite=112523212464062464]]}, lastAppliedIndex=6, lastAppliedTerm=1, rebalanceFutureReference=null, closed=false]]
[2024-05-29T10:32:43,694][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Partition data [node=itdttntr_n_20002, groupId=2_part_0, data={}]
[2024-05-29T10:32:43,694][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Index data [node=itdttntr_n_20002, groupId=2_part_0, data={}]
[2024-05-29T10:32:43,695][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Tx state data [node=itdttntr_n_20002, groupId=2_part_0, data=TestTxStateStorage [storage=ConcurrentSkipListMap {018fc343-fbd8-0000-ffff-ffff00000001=TxMeta [txState=COMMITTED, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:624 +0300, logical=0, composite=112523212464062464]]}, lastAppliedIndex=6, lastAppliedTerm=1, rebalanceFutureReference=null, closed=false]]
[2024-05-29T10:32:43,695][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Volatile tx state data [node=itdttntr_n_20002, data={018fc343-fb5d-0000-ffff-ffff00000001=TxStateMeta [txState=COMMITTED, txCoordinatorId=a0b6c316-1a11-4bc6-a146-6f9ed6fb5d5e, commitPartitionId=null, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:555 +0300, logical=0, composite=112523212459540480], initialVacuumObservationTimestamp=null, cleanupCompletionTimestamp=null], 018fc343-fbd8-0000-ffff-ffff00000001=TxStateMeta [txState=COMMITTED, txCoordinatorId=null, commitPartitionId=0_part_0, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:624 +0300, logical=0, composite=112523212464062464], initialVacuumObservationTimestamp=null, cleanupCompletionTimestamp=null]}]

[2024-05-29T10:32:43,696][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Partition data [node=itdttntr_n_20000, groupId=0_part_0, data={RowId [partitionId=0, uuid=af8c50c3-48f3-48b2-9785-bcbe481ce55c]=VersionChain [rowId=RowId [partitionId=0, uuid=af8c50c3-48f3-48b2-9785-bcbe481ce55c], row=org.apache.ignite.internal.schema.BinaryRowImpl@c9f591a9, ts=HybridTimestamp [physical=2024-05-29 10:32:43:555 +0300, logical=0, composite=112523212459540480], txId=null, commitTableId=null, commitPartitionId=-1], RowId [partitionId=0, uuid=b64eae79-3190-4e68-8b8a-c6e05c3d1d27]=VersionChain [rowId=RowId [partitionId=0, uuid=b64eae79-3190-4e68-8b8a-c6e05c3d1d27], row=org.apache.ignite.internal.schema.BinaryRowImpl@c9f60608, ts=HybridTimestamp [physical=2024-05-29 10:32:43:555 +0300, logical=0, composite=112523212459540480], txId=null, commitTableId=null, commitPartitionId=-1]}]
[2024-05-29T10:32:43,696][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Index data [node=itdttntr_n_20000, groupId=0_part_0, data={java.nio.HeapByteBuffer[pos=0 lim=3 cap=3]=[RowId [partitionId=0, uuid=b64eae79-3190-4e68-8b8a-c6e05c3d1d27]], java.nio.HeapByteBuffer[pos=0 lim=3 cap=3]=[RowId [partitionId=0, uuid=af8c50c3-48f3-48b2-9785-bcbe481ce55c]]}]
[2024-05-29T10:32:43,696][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Tx state data [node=itdttntr_n_20000, groupId=0_part_0, data=TestTxStateStorage [storage=ConcurrentSkipListMap {018fc343-fbd8-0000-ffff-ffff00000001=TxMeta [txState=COMMITTED, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:624 +0300, logical=0, composite=112523212464062464]]}, lastAppliedIndex=6, lastAppliedTerm=1, rebalanceFutureReference=null, closed=false]]
[2024-05-29T10:32:43,696][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Partition data [node=itdttntr_n_20000, groupId=2_part_0, data={}]
[2024-05-29T10:32:43,696][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Index data [node=itdttntr_n_20000, groupId=2_part_0, data={}]
[2024-05-29T10:32:43,697][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Tx state data [node=itdttntr_n_20000, groupId=2_part_0, data=TestTxStateStorage [storage=ConcurrentSkipListMap {018fc343-fbd8-0000-ffff-ffff00000001=TxMeta [txState=COMMITTED, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:624 +0300, logical=0, composite=112523212464062464]]}, lastAppliedIndex=6, lastAppliedTerm=1, rebalanceFutureReference=null, closed=false]]
[2024-05-29T10:32:43,697][INFO ][main][ItTxDistributedTestThreeNodesThreeReplicas] Volatile tx state data [node=itdttntr_n_20000, data={018fc343-fb5d-0000-ffff-ffff00000001=TxStateMeta [txState=COMMITTED, txCoordinatorId=a0b6c316-1a11-4bc6-a146-6f9ed6fb5d5e, commitPartitionId=null, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:555 +0300, logical=0, composite=112523212459540480], initialVacuumObservationTimestamp=null, cleanupCompletionTimestamp=null], 018fc343-fbd8-0000-ffff-ffff00000001=TxStateMeta [txState=COMMITTED, txCoordinatorId=a0b6c316-1a11-4bc6-a146-6f9ed6fb5d5e, commitPartitionId=0_part_0, commitTimestamp=HybridTimestamp [physical=2024-05-29 10:32:43:624 +0300, logical=0, composite=112523212464062464], initialVacuumObservationTimestamp=null, cleanupCompletionTimestamp=1716967963695]}]