Investigate weird behaviour after the synced restart from a boot-snapshot. see log
Closed this issue · 0 comments
`[2021-12-21T13:58:07.918920000Z INFO solana_core::window_service] num addresses: 0, top packets by source: [(127.0.0.1:10008, 1100)]
[2021-12-21T13:58:08.367957000Z WARN solana_rpc::rpc] Bank with Finalized not found at slot: 414
[2021-12-21T13:58:08.369039000Z INFO solana_rpc::rpc] RPC using optimistically confirmed slot: 446
[2021-12-21T13:58:08.371762000Z INFO solana_rpc::rpc] RPC using optimistically confirmed slot: 446
[2021-12-21T13:58:08.372449000Z WARN solana_rpc::rpc_health] health check: latest_account_hash_slot not available
[2021-12-21T13:58:08.648019000Z INFO solana_core::replay_stage] new fork:447 parent:446 root:446
DMLOG BLOCK_WORK 446 447 full 28ZUePiPKuienpnHpBbgZaBnrT9EZcuf5CjZkgCf1nUM 65 1 63 0 0 0 FBhATnFNmqBWbnEBfktQ4vtCupAyiz1Tz9P357C8Sdue 0 T;5MR1bVMzMbhzb36h6UbXT9A4ZnUVvZUrQ9t7LbysdZeYnGjEmWphzwoJthj6GSmeCciSX1qeKvoq2wiyjG6oqodj
[2021-12-21T13:58:08.870335000Z WARN solana_ledger::blockstore_processor] Unexpected validator error: AlreadyProcessed, transaction: Transaction { signatures: [5MR1bVMzMbhzb36h6UbXT9A4ZnUVvZUrQ9t7LbysdZeYnGjEmWphzwoJthj6GSmeCciSX1qeKvoq2wiyjG6oqodj], message: Message { header: MessageHeader { num_required_signatures: 1, num_readonly_signed_accounts: 0, num_readonly_unsigned_accounts: 3 }, account_keys: [B8RbEjY1rGgCthd6v5jzz3wM2hKLenu1hgby4NmTXjm8, 3CL4UGARKX26s23y7uNPSgWeqZW1F67c9F6m1u5YLvjL, SysvarS1otHashes111111111111111111111111111, SysvarC1ock11111111111111111111111111111111, Vote111111111111111111111111111111111111111], recent_blockhash: FBhATnFNmqBWbnEBfktQ4vtCupAyiz1Tz9P357C8Sdue, instructions: [CompiledInstruction { program_id_index: 4, accounts: [1, 2, 3, 0], data: [2, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 190, 1, 0, 0, 0, 0, 0, 0, 16, 203, 121, 90, 96, 54, 237, 242, 248, 205, 157, 116, 90, 184, 145, 234, 148, 235, 170, 6, 25, 31, 89, 240, 46, 153, 94, 74, 237, 149, 59, 6, 1, 81, 220, 193, 97, 0, 0, 0, 0] }] } }
[2021-12-21T13:58:08.871167000Z ERROR solana_metrics::metrics] datapoint: validator_process_entry_error error="error: AlreadyProcessed, transaction: Transaction { signatures: [5MR1bVMzMbhzb36h6UbXT9A4ZnUVvZUrQ9t7LbysdZeYnGjEmWphzwoJthj6GSmeCciSX1qeKvoq2wiyjG6oqodj], message: Message { header: MessageHeader { num_required_signatures: 1, num_readonly_signed_accounts: 0, num_readonly_unsigned_accounts: 3 }, account_keys: [B8RbEjY1rGgCthd6v5jzz3wM2hKLenu1hgby4NmTXjm8, 3CL4UGARKX26s23y7uNPSgWeqZW1F67c9F6m1u5YLvjL, SysvarS1otHashes111111111111111111111111111, SysvarC1ock11111111111111111111111111111111, Vote111111111111111111111111111111111111111], recent_blockhash: FBhATnFNmqBWbnEBfktQ4vtCupAyiz1Tz9P357C8Sdue, instructions: [CompiledInstruction { program_id_index: 4, accounts: [1, 2, 3, 0], data: [2, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 190, 1, 0, 0, 0, 0, 0, 0, 16, 203, 121, 90, 96, 54, 237, 242, 248, 205, 157, 116, 90, 184, 145, 234, 148, 235, 170, 6, 25, 31, 89, 240, 46, 153, 94, 74, 237, 149, 59, 6, 1, 81, 220, 193, 97, 0, 0, 0, 0] }] } }"
DMLOG BATCH_FILE dmlog-1-0
DMLOG BATCHES_END
DMLOG BLOCK_FAILED 447 Err(
InvalidTransaction(
AlreadyProcessed,
),
)
[2021-12-21T13:58:08.890797000Z ERROR solana_metrics::metrics] datapoint: replay-stage-mark_dead_slot error="error: InvalidTransaction(AlreadyProcessed)" slot=447i
[2021-12-21T13:58:08.890836000Z INFO solana_core::cluster_slot_state_verifier] check_slot_agrees_with_cluster()
slot: 447,
root: 446,
frozen_hash: Some(11111111111111111111111111111111),
update: Dead
[2021-12-21T13:58:08.890912000Z INFO solana_core::cluster_slot_state_verifier] check_slot_agrees_with_cluster() state
is_local_replay_duplicate_confirmed: false,
cluster_duplicate_confirmed_hash: None,
is_slot_duplicate: false,
is_dead: true
[2021-12-21T13:58:09.703236000Z INFO solana_core::repair_service] repair_stats: [(505, 63), (477, 64), (456, 68), (451, 62), (511, 54), (486, 61), (460, 63), (502, 62), (491, 61), (500, 63), (467, 63), (476, 64), (459, 64), (507, 63), (452, 63), (457, 67), (466, 63), (478, 64), (480, 63), (504, 63), (509, 63), (503, 63), (450, 63), (501, 63), (462, 64), (494, 62), (458, 61), (471, 63), (497, 63), (499, 63), (447, 62), (506, 63), (487, 63), (465, 63), (508, 63), (473, 64), (461, 63), (464, 64), (470, 64), (481, 62), (468, 64), (482, 62), (488, 62), (493, 63), (475, 64), (474, 63), (484, 62), (449, 59), (495, 63), (496, 63), (492, 63), (483, 63), (510, 63), (498, 63), (463, 63), (479, 62), (490, 63), (485, 63), (472, 63), (489, 63), (448, 63), (454, 63), (455, 67), (469, 62), (453, 62), (446, 8), (977, 26), (631, 1), (620, 1), (609, 1), (576, 1), (565, 1), (499, 1), (554, 1), (488, 1), (466, 1), (598, 1), (642, 1), (521, 1), (510, 1), (974, 26), (976, 26), (532, 1), (978, 8), (477, 1), (587, 1), (455, 1), (543, 1), (975, 26)]
[2021-12-21T13:58:09.922516000Z INFO solana_core::window_service] num addresses: 0, top packets by source: [(127.0.0.1:10008, 5477), (127.0.0.1:10009, 384)]
[2021-12-21T13:58:10.377474000Z WARN solana_rpc::rpc] Bank with Finalized not found at slot: 414
[2021-12-21T13:58:10.381551000Z INFO solana_rpc::rpc] RPC using optimistically confirmed slot: 446
[2021-12-21T13:58:10.399149000Z INFO solana_rpc::rpc] RPC using optimistically confirmed slot: 446
[2021-12-21T13:58:10.400478000Z WARN solana_rpc::rpc_health] health check: latest_account_hash_slot not available
[2021-12-21T13:58:11.929582000Z INFO solana_core::window_service] num addresses: 0, top packets by source: [(127.0.0.1:10008, 8505), (127.0.0.1:10009, 524)]
[2021-12-21T13:58:12.406024000Z WARN solana_rpc::rpc] Bank with Finalized not found at slot: 414
[2021-12-21T13:58:12.407116000Z INFO solana_rpc::rpc] RPC using optimistically confirmed slot: 446
[2021-12-21T13:58:12.411475000Z INFO solana_rpc::rpc] RPC using optimistically confirmed slot: 446
[2021-12-21T13:58:12.412255000Z WARN solana_rpc::rpc_health] health check: latest_account_hash_slot not available
[2021-12-21T13:58:12.746488000Z INFO solana_core::repair_service] repair_stats: [(527, 63), (599, 62), (531, 63), (695, 63), (590, 62), (650, 62), (518, 63), (561, 63), (578, 62), (547, 63), (583, 63), (596, 63), (537, 63), (629, 63), (666, 63), (572, 63), (676, 62), (617, 63), (681, 63), (556, 62), (625, 63), (692, 61), (668, 63), (624, 63), (673, 63), (563, 63), (557, 63), (579, 63), (631, 63), (609, 62), (611, 63), (677, 63), (574, 62), (540, 63), (672, 63), (585, 63), (548, 63), (558, 63), (687, 63), (529, 63), (573, 63), (615, 63), (598, 63), (577, 63), (516, 62), (593, 63), (582, 63), (623, 63), (627, 63), (635, 63), (696, 63), (559, 63), (614, 63), (690, 63), (560, 63), (549, 63), (511, 9), (515, 63), (532, 62), (571, 63), (613, 63), (536, 63), (521, 63), (580, 61), (564, 62), (586, 63), (603, 62), (552, 62), (524, 63), (587, 63), (591, 63), (626, 62), (639, 62), (647, 63), (653, 63), (655, 63), (663, 63), (634, 63), (569, 63), (607, 62), (679, 63), (533, 63), (600, 62), (654, 63), (684, 62), (686, 62), (597, 63), (693, 63), (649, 62), (659, 62), (669, 63), (546, 63), (632, 62), (566, 62), (661, 62), (662, 62), (641, 63), (622, 62), (602, 63), (658, 62), (525, 63), (544, 62), (674, 62), (565, 63), (541, 63), (592, 62), (642, 61), (604, 62), (652, 62), (610, 62), (678, 62), (685, 63), (697, 62), (621, 63), (643, 63), (694, 63), (555, 63), (581, 63), (512, 63), (645, 63), (630, 62), (551, 63), (601, 63), (636, 63), (517, 63), (588, 62), (595, 63), (619, 63), (637, 63), (523, 63), (660, 63), (680, 63), (688, 62), (545, 63), (664, 63), (682, 63), (550, 62), (689, 63), (670, 62), (638, 62), (543, 62), (633, 63), (514, 62), (530, 62), (667, 63), (605, 63), (594, 62), (584, 63), (538, 62), (628, 62), (683, 63), (620, 62), (528, 63), (526, 63), (520, 62), (539, 63), (542, 63), (651, 63), (691, 62), (534, 62), (675, 63), (618, 62), (567, 63), (554, 63), (640, 62), (589, 63), (644, 63), (513, 63), (535, 62), (553, 62), (575, 63), (568, 63), (576, 63), (606, 62), (608, 63), (646, 62), (648, 62), (656, 62), (657, 63), (671, 63), (570, 62), (519, 63), (616, 63), (665, 61), (699, 34), (562, 62), (612, 63), (522, 62), (698, 62), (446, 23), (976, 23), (977, 23), (974, 23), (978, 23), (975, 23)]
[2021-12-21T13:58:13.694565000Z INFO solana_gossip::cluster_info]
IP Address |Age(ms)| Node identifier | Version |Gossip|TPUvote| TPU |TPUfwd| TVU |TVUfwd|Repair|ServeR|ShredVer
------------------+-------+----------------------------------------------+---------+------+------+-------+------+------+------+------+------+--------
127.0.0.1 me| 2362 | GfzWVoMCKfZhahdb6TuhP614GeQYN1ZYtLKj741fMcXv | 1.7.15 | 9001 | 11005| 11003| 11004| 11001| 11002| 11007| 11008| 29919
127.0.0.1 | 146 | B8RbEjY1rGgCthd6v5jzz3wM2hKLenu1hgby4NmTXjm8 | 1.7.15 | 8001 | 10005| 10003| 10004| 10001| 10002| 10007| 10008| 29919
Nodes: 2
RPC Address |Age(ms)| Node identifier | Version | RPC |PubSub|ShredVer
------------------+-------+----------------------------------------------+---------+------+------+--------
127.0.0.1 me| 2362 | GfzWVoMCKfZhahdb6TuhP614GeQYN1ZYtLKj741fMcXv | 1.7.15 | 9890 | 9891 | 29919
127.0.0.1 | 146 | B8RbEjY1rGgCthd6v5jzz3wM2hKLenu1hgby4NmTXjm8 | 1.7.15 | 8899 | 8900 | 29919
RPC Enabled Nodes: 2
[2021-12-21T13:58:13.950861000Z INFO solana_core::window_service] num addresses: 0, top packets by source: [(127.0.0.1:10008, 8505), (127.0.0.1:10009, 472)]
[2021-12-21T13:58:14.417086000Z WARN solana_rpc::rpc] Bank with Finalized not found at slot: 414
[2021-12-21T13:58:14.417924000Z INFO solana_rpc::rpc] RPC using optimistically confirmed slot: 446
[2021-12-21T13:58:14.421401000Z INFO solana_rpc::rpc] RPC using optimistically confirmed slot: 446
[2021-12-21T13:58:14.422236000Z WARN solana_rpc::rpc_health] health check: latest_account_hash_slot not available
[2021-12-21T13:58:15.856192000Z INFO solana_core::repair_service] repair_stats: [(833, 63), (815, 63), (837, 63), (714, 63), (791, 63), (740, 62), (763, 63), (829, 63), (860, 62), (766, 62), (753, 63), (805, 63), (780, 63), (818, 63), (826, 63), (811, 63), (796, 62), (748, 62), (812, 63), (758, 63), (827, 63), (712, 62), (759, 63), (760, 62), (750, 63), (832, 63), (809, 63), (857, 63), (788, 63), (863, 63), (872, 62), (862, 63), (751, 63), (709, 63), (841, 63), (754, 62), (844, 62), (749, 63), (738, 62), (787, 63), (718, 62), (703, 63), (776, 61), (853, 63), (727, 63), (825, 63), (786, 62), (835, 61), (881, 63), (855, 63), (834, 63), (744, 63), (778, 62), (711, 63), (764, 63), (777, 63), (794, 63), (771, 63), (799, 63), (821, 62), (708, 62), (830, 61), (756, 62), (795, 63), (722, 62), (856, 61), (877, 63), (752, 62), (882, 62), (854, 63), (721, 63), (713, 62), (801, 63), (859, 63), (707, 62), (723, 63), (843, 63), (781, 63), (773, 63), (789, 63), (808, 62), (820, 62), (866, 62), (884, 63), (885, 63), (755, 63), (765, 63), (876, 62), (790, 63), (704, 62), (887, 27), (716, 62), (717, 63), (725, 63), (732, 61), (823, 63), (836, 62), (846, 63), (868, 62), (871, 63), (745, 63), (867, 63), (706, 62), (743, 63), (770, 62), (784, 62), (807, 61), (813, 63), (839, 62), (869, 62), (803, 63), (874, 62), (879, 63), (850, 62), (741, 62), (768, 62), (775, 63), (806, 62), (842, 62), (702, 62), (851, 63), (705, 63), (792, 62), (847, 62), (864, 63), (715, 63), (761, 63), (817, 63), (772, 62), (719, 63), (804, 62), (734, 63), (822, 63), (870, 63), (746, 62), (726, 62), (757, 63), (762, 62), (831, 63), (742, 63), (800, 62), (845, 63), (880, 63), (735, 63), (729, 62), (828, 63), (733, 63), (730, 62), (747, 63), (819, 63), (878, 63), (873, 62), (700, 62), (861, 62), (783, 62), (731, 63), (736, 62), (883, 63), (797, 63), (720, 62), (785, 63), (810, 63), (814, 63), (774, 63), (852, 63), (728, 62), (701, 63), (710, 62), (838, 61), (737, 63), (767, 63), (699, 29), (769, 63), (793, 63), (858, 62), (875, 63), (739, 63), (802, 61), (865, 63), (779, 63), (848, 63), (798, 62), (840, 62), (724, 63), (886, 62), (782, 62), (816, 62), (824, 62), (849, 62), (446, 23), (977, 23), (974, 23), (975, 23), (976, 23), (978, 23)]
[2021-12-21T13:58:15.951494000Z INFO solana_core::window_service] num addresses: 0, top packets by source: [(127.0.0.1:10008, 8505), (127.0.0.1:10009, 482)]
[2021-12-21T13:58:16.431314000Z WARN solana_rpc::rpc] Bank with Finalized not found at slot: 414
[2021-12-21T13:58:16.434050000Z INFO solana_rpc::rpc] RPC using optimistically confirmed slot: 446
[2021-12-21T13:58:16.436902000Z INFO solana_rpc::rpc] RPC using optimistically confirmed slot: 446
[2021-12-21T13:58:16.437642000Z WARN solana_rpc::rpc_health] health check: latest_account_hash_slot not available`