This repository was archived by the owner on Nov 15, 2023. It is now read-only.
This repository was archived by the owner on Nov 15, 2023. It is now read-only.
Unexpected cache value for storage leading to state root mismatch #7964
Description
We have been observing state root mismatch at random interval (from 5 min to some hours) on different nodes (often only 1 at a time but some time multiple nodes at the same block).
Restarting the node always allowed the node to process the block and go on.
We have been monitoring the nodes with TRACE logs and were able to capture a block that failed on 1 node with a state mismatch.
Both of the nodes are Full nodes, not producing blocks.
I filtered the logs to only track 2 things:
- which block it is (using db:DB Commit, and Call Core_execute_block which display the previous block)
- The storage key that is failing (https://github.com/PureStake/moonbeam/blob/master/pallets/stake/src/lib.rs#L297)
(I also added few comments starting with # at the end of some lines for better understanding)
The pallet using that storage key simply read it and add +20 (see https://github.com/PureStake/moonbeam/blob/master/pallets/stake/src/lib.rs#L627 for more details)
This is the failing node
1. 2021-01-22 18:01:16.160 TRACE tokio-runtime-worker state:943e: Call Core_execute_block at Block Some(0x83b150af1b471cbd664c7d078d05524e61937c8bb173b3e5d435c79f45a7a887). Input=83b150af1b471cbd664c7d078d05524e61937c8bb173b3e5d435c79f45a7a887817b0149973bc34ac54b39c1ced7440440487c1e70e5144e7d4ff3d83dc5d1d5eee4a1ba0c01925b486e159eaf525949219bc85cd580b85614b09ac17f2ea2a24c4c08046175746850be373fc7be685e9a4ab00dd665dae5c553489add0466726f6e880128a548e6a5c19b3869aa096c0c820d649021c1fbc10785a75a788cb7c6791766000c280401000b5294412b7701bd130405029502382b6b5eaeaad15973c11879ef56e13a9967d100f9b52dd1308ed2751eee31767d7bd39dcd23d53fe794d07221a0a7c6f7eda8e261e9189f8d3e3a02af177df0bc2f61f60cc0ae0b718f6e0e45221f5bce53079277635b523e7bd96e3443dce6f95d08046175746850be373fc7be685e9a4ab00dd665dae5c553489add0466726f6e8801715d8cbb30c6ad6abb4e2ebf3e38caa61a5a7dcf49cfd0f669d19bed5d4cddd800b03f0000f39c2312aacc9dcb0d9d8a4df4b6d46097c8c7b5cc5fe2c5b56aeb2e139717930000000000000000000000000000000000000000000000000000000000000000000000200300005000008000000000000000000000000000000000000001dc4000000000000018f49e207f03cfdce586301014700e2c25930041585f078d434d6125b40443fe11fd292d13a410000008004c5f0ec2d17a76153ff51817f12d9cfc3c7f0400c106807ff6802ca40549562ffe6b52b99b82732a11693a9f94e719eb6091a28361553b7e1d6f8016120a954e0f8fc685a2b0a14b633f49e27e1268273f5f2d4b881d58b510f4db80837899b465dc8b2bc6e1c8ea078e124852dfdf7cd478d549d60dfd2e4867e76d80f0e739e245e4602295e1f12ac5d0f22b1d7a599772906194f38da563d749b95280e414e10544bd675728129b47430c6a97a6c5a7d63cbc6b05943db7995f5fbb8780ad9821a7d9a8dc8edca1c04e54694b8b6e9eac79ccf5cd52fbdfbc44dd40bb61806ece38b4bc81ae7502f2fefc79d81b92bf5a1e33c8f06928b6bb464266cabe12800aa81235e9b476c078c6c84b87498ed08f68db32a039f67811b3e8c14775a34f80ba7052563c97b91cccc3a3762e0a8d73a0fd2018bd63932fdf6e6dfb8e99870580f53f4d040f482565f713cacd84e1c23c45b7aa0979b2500e112c9f5ccab644318091188f5e6b7c3c7ad6e07e9fe3257e06da33cf5c39b20ee649c532503f7559df80974da04ec2f2a432413995b1c30d9903e6c69b63d25ea3564c3fd604513c045480036a41022c18eae5b4b1dd688de06a91e7eec5cbd9070dae6f93a4df1cd5618635037f0006de3d8a54d27e44a9d5ce189618f22db4b49d95320d9021994c850f25b8e385a50200005000008000000800000000200000000400000500000005000000580200002c010000000020030004000000286bee0000000004000000040000000500000000000000000000000000000000000000000000000000000000000000000000000800000000200000040000000400000000040000b004000000000000000000001400000004000000040000000000000000000000000a00000000000000000000000000000000000000a9019e0da05ca59913bc38a8630590f2627c014180ea1b6ee9e85ed26601a6b3d231a5fd858dbae91339c1ec636b48b04a50c49537585f078d434d6125b40443fe11fd292d13a410000008007c7700e67da63472835bb0b737093a19ad4cb6ff6f7d467b87a9e80300000400150180210080485c9030f38b1203d2249210673d214762e89fffe6d6c23e2c02dc8ab38feb9180f2ce141c02c934f343545350b70e54c8c2a0bb12f886462797399672b145ff0c9901801804806d8032309590a0d9476546c43094b4b94f2237e8e67a52af89716a59953d379480aebb1dfa081e0f528a33c48cc0d64717ff2e6de6f73e001bc0c608d24f5b79b78005dcbc38e4827511881a54616f9e17405237f8b14edaeb53f19ca9d4280d28215c040c00be373fc7be685e9a4ab00dd665dae5c553489add
2. 2021-01-22 18:01:16.161 TRACE tokio-runtime-worker sc_client_db::storage_cache:Found in shared cache: 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add
3. 2021-01-22 18:01:16.161 TRACE tokio-runtime-worker state:943e: Get 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add=Some(28000000) # valid key for account 0x.....89add
4. 2021-01-22 18:01:16.161 TRACE tokio-runtime-worker state:943e: Put 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add=Some(3c000000)
5. 2021-01-22 18:01:16.170 DEBUG tokio-runtime-worker db:DB Commit 0xd0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685 (7904), best = false
6. 2021-01-22 18:01:16.170 DEBUG tokio-runtime-worker db:DB Commit 0xd0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685 (7904), best = true
7. 2021-01-22 18:07:07.796 TRACE tokio-runtime-worker state:1a38: Call Core_execute_block at Block Some(0xd0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685). Input=d0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685857b1bf62274828cc0f601591107d246f10936f625814ba03ae2d3c2dc5788fe9710cb1c8108a3fdc301f41afd3a89f9cfff7d3def434c65b49845bd0192cd1c4c6e0804617574685005160bacc74e6af4d755f9dd6d409fc99ee918fa0466726f6e88010267806f0d0e51de91c5e0a8eb630a66d7e89a5f042fb68a781afda2fb07c8dc000c280401000b0ac3412b7701bd13040502950283b150af1b471cbd664c7d078d05524e61937c8bb173b3e5d435c79f45a7a887817b0149973bc34ac54b39c1ced7440440487c1e70e5144e7d4ff3d83dc5d1d5eee4a1ba0c01925b486e159eaf525949219bc85cd580b85614b09ac17f2ea2a24c4c08046175746850be373fc7be685e9a4ab00dd665dae5c553489add0466726f6e880128a548e6a5c19b3869aa096c0c820d649021c1fbc10785a75a788cb7c679176600b23f0000d581131ca0a90781203d1fd2b7ac91ee8c4ef07a0cabed12c7c8940bb2c6cba70000000000000000000000000000000000000000000000000000000000000000000000200300005000008000000000000000000000000000000000000001de40000000000000189901801804806d8032309590a0d9476546c43094b4b94f2237e8e67a52af89716a59953d379480aebb1dfa081e0f528a33c48cc0d64717ff2e6de6f73e001bc0c608d24f5b79b78010809b7c3d133876803f5891b48cbff4a48585d529f32b86af570c86680117a7a9019e0da05ca59913bc38a8630590f2627c0141805beb60d8935cbdf1529b2119521df93f0ca1a4f84349cf1ced38401e5907b3f5585f078d434d6125b40443fe11fd292d13a410000008007c7700e67da63472835bb0b737093a19ad4cb6ff6f7d467b87a9e8030000040035037f0006de3d8a54d27e44a9d5ce189618f22db4b49d95320d9021994c850f25b8e385a50200005000008000000800000000200000000400000500000005000000580200002c010000000020030004000000286bee0000000004000000040000000500000000000000000000000000000000000000000000000000000000000000000000000800000000200000040000000400000000040000b004000000000000000000001400000004000000040000000000000000000000000a00000000000000000000000000000000000000150180210080a6a5805cd127cecb9decc694386b416b76567697e1094bac14e718929179076680f2ce141c02c934f343545350b70e54c8c2a0bb12f886462797399672b145ff0cf49e207f03cfdce586301014700e2c25930041585f078d434d6125b40443fe11fd292d13a410000008004c5f0ec2d17a76153ff51817f12d9cfc3c7f0400c106807ff6802ca40549562ffe6b52b99b82732a11693a9f94e719eb6091a28361553b7e1d6f80e40aec7f2b9ca3a8fa0952bb2898b94b1f5e7a4b1d713e5e8844b588b152d1c0804451323afe908224fd96ab1a2ba76ef3ee9d1b7ab81e04b0605d103912feb2f98057af15b60ec853bab744e556ba4b2fef2d3a9dcd6038e7a3f078294e3e239c1980e414e10544bd675728129b47430c6a97a6c5a7d63cbc6b05943db7995f5fbb8780ad9821a7d9a8dc8edca1c04e54694b8b6e9eac79ccf5cd52fbdfbc44dd40bb61809f684e900656c53b05aef9dbe921006ee18dd942177e060d9da16bf1f055a3c3800aa81235e9b476c078c6c84b87498ed08f68db32a039f67811b3e8c14775a34f80ba7052563c97b91cccc3a3762e0a8d73a0fd2018bd63932fdf6e6dfb8e998705801ff6bd8cc8c437422dfcd3436f3a64b91b0299840bf037a2cb65fe538ef7a6ea8091188f5e6b7c3c7ad6e07e9fe3257e06da33cf5c39b20ee649c532503f7559df80974da04ec2f2a432413995b1c30d9903e6c69b63d25ea3564c3fd604513c045480cc4045551a5a410e1cbf235d9d7a1eafa40201cd7bea87351747fadfa4d6afa55c040c0005160bacc74e6af4d755f9dd6d409fc99ee918fa
8. 2021-01-22 18:07:07.798 TRACE tokio-runtime-worker sc_client_db::storage_cache:Found in shared cache: 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000296e8cd9add026bf61c4f754972ac20605160bacc74e6af4d755f9dd6d409fc99ee918fa
9. 2021-01-22 18:07:07.798 TRACE tokio-runtime-worker state:1a38: Get 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000296e8cd9add026bf61c4f754972ac20605160bacc74e6af4d755f9dd6d409fc99ee918fa=Some(14000000) # this is a different key (account 0x......918fa)
0. 2021-01-22 18:07:07.798 TRACE tokio-runtime-worker state:1a38: Put 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000296e8cd9add026bf61c4f754972ac20605160bacc74e6af4d755f9dd6d409fc99ee918fa=Some(28000000) # this is a different key (account 0x......918fa)
10. 2021-01-22 18:07:07.806 DEBUG tokio-runtime-worker db:DB Commit 0xd44215f3f482eec3f8326a9621f1954f68fc857829e33ec2a0dac67a44dc9ac5 (7905), best = true
11. 2021-01-22 18:07:07.809 TRACE tokio-runtime-worker state:1789: Call Core_execute_block at Block Some(0xd44215f3f482eec3f8326a9621f1954f68fc857829e33ec2a0dac67a44dc9ac5). Input=d44215f3f482eec3f8326a9621f1954f68fc857829e33ec2a0dac67a44dc9ac5897b9204c82355aaafdcaf52f041214bc49f94c16a00f6ca9850bd18f2cdd3da4d978f11e22194b4518a529ebd0a39f58e0ecd54b2ecd29f2dd1bf9039f72ed13c1108046175746850be373fc7be685e9a4ab00dd665dae5c553489add0466726f6e8801af97ca9131cc8f4bfc5020f298594a6491d0d55bdbd6f5f0b2e479743d537f6d000c280401000be9f1412b7701bd130405029502d0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685857b1bf62274828cc0f601591107d246f10936f625814ba03ae2d3c2dc5788fe9710cb1c8108a3fdc301f41afd3a89f9cfff7d3def434c65b49845bd0192cd1c4c6e0804617574685005160bacc74e6af4d755f9dd6d409fc99ee918fa0466726f6e88010267806f0d0e51de91c5e0a8eb630a66d7e89a5f042fb68a781afda2fb07c8dc00b43f000014c3635523f765d4d0a341f20755c5a3b16f2b2a239b8a4fe6e4ea00c9293bf40000000000000000000000000000000000000000000000000000000000000000000000200300005000008000000000000000000000000000000000000001e04000000000000018c106807ff6802ca40549562ffe6b52b99b82732a11693a9f94e719eb6091a28361553b7e1d6f807cc87704adc5ba1a479c07d47692b70ed3d2c5110f22d878342c9f130cbc3f6880baf242a7e0dd910406fbf3ef7042ae7c0048e22962378a6f77559a814c14589b800f8e85b0453c59df2b556dde6d97b349be203d96f3de1b08ec516f8822d2234d80e414e10544bd675728129b47430c6a97a6c5a7d63cbc6b05943db7995f5fbb8780ad9821a7d9a8dc8edca1c04e54694b8b6e9eac79ccf5cd52fbdfbc44dd40bb6180aac43c4819dfc8076857bc4207df0728ff8718ff5643b8d114db3cff83db6e62800aa81235e9b476c078c6c84b87498ed08f68db32a039f67811b3e8c14775a34f80ba7052563c97b91cccc3a3762e0a8d73a0fd2018bd63932fdf6e6dfb8e998705802a861f1d1699549a05c7c3073d5398e948b7ed4d1350a45e05a4b339b6ebe2ac8091188f5e6b7c3c7ad6e07e9fe3257e06da33cf5c39b20ee649c532503f7559df80974da04ec2f2a432413995b1c30d9903e6c69b63d25ea3564c3fd604513c045480cb8e86fd4e7f2fd7d521de7a4a4cbb7b0a7f05a7cbc93ba049ae2b46828e45ae35037f0006de3d8a54d27e44a9d5ce189618f22db4b49d95320d9021994c850f25b8e385a50200005000008000000800000000200000000400000500000005000000580200002c010000000020030004000000286bee0000000004000000040000000500000000000000000000000000000000000000000000000000000000000000000000000800000000200000040000000400000000040000b004000000000000000000001400000004000000040000000000000000000000000a00000000000000000000000000000000000000f49e207f03cfdce586301014700e2c25930041585f078d434d6125b40443fe11fd292d13a410000008004c5f0ec2d17a76153ff51817f12d9cfc3c7f04001501802100800141ae08db3446b1d71f36c83b4e840817ae553d816a1134a8c206c69026df2a80f2ce141c02c934f343545350b70e54c8c2a0bb12f886462797399672b145ff0c9901801804806d8032309590a0d9476546c43094b4b94f2237e8e67a52af89716a59953d379480aebb1dfa081e0f528a33c48cc0d64717ff2e6de6f73e001bc0c608d24f5b79b7802b35dd68944f8bc169d854a45ef1267991460df70f2e61815d84b719a968b53fa9019e0da05ca59913bc38a8630590f2627c0141808fddb9ddcad95600d1f5b3049f95a5bac21937cf27184955e4886b3d76a2267e585f078d434d6125b40443fe11fd292d13a410000008007c7700e67da63472835bb0b737093a19ad4cb6ff6f7d467b87a9e803000004005c040c00be373fc7be685e9a4ab00dd665dae5c553489add
12. 2021-01-22 18:07:07.810 TRACE tokio-runtime-worker sc_client_db::storage_cache:Found in shared cache: 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add
13. 2021-01-22 18:07:07.810 TRACE tokio-runtime-worker state:1789: Get 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add=Some(28000000) # WRONG VALUE for account 0x.....89add
14. 2021-01-22 18:07:07.810 TRACE tokio-runtime-worker state:1789: Put 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add=Some(3c000000)
15. 2021-01-22 18:07:07.949 TRACE tokio-runtime-worker state:fd38: Call Core_execute_block at Block Some(0xd44215f3f482eec3f8326a9621f1954f68fc857829e33ec2a0dac67a44dc9ac5). Input=d44215f3f482eec3f8326a9621f1954f68fc857829e33ec2a0dac67a44dc9ac5897b9204c82355aaafdcaf52f041214bc49f94c16a00f6ca9850bd18f2cdd3da4d978f11e22194b4518a529ebd0a39f58e0ecd54b2ecd29f2dd1bf9039f72ed13c1108046175746850be373fc7be685e9a4ab00dd665dae5c553489add0466726f6e8801af97ca9131cc8f4bfc5020f298594a6491d0d55bdbd6f5f0b2e479743d537f6d000c280401000be9f1412b7701bd130405029502d0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685857b1bf62274828cc0f601591107d246f10936f625814ba03ae2d3c2dc5788fe9710cb1c8108a3fdc301f41afd3a89f9cfff7d3def434c65b49845bd0192cd1c4c6e0804617574685005160bacc74e6af4d755f9dd6d409fc99ee918fa0466726f6e88010267806f0d0e51de91c5e0a8eb630a66d7e89a5f042fb68a781afda2fb07c8dc00b43f000014c3635523f765d4d0a341f20755c5a3b16f2b2a239b8a4fe6e4ea00c9293bf40000000000000000000000000000000000000000000000000000000000000000000000200300005000008000000000000000000000000000000000000001e04000000000000018c106807ff6802ca40549562ffe6b52b99b82732a11693a9f94e719eb6091a28361553b7e1d6f807cc87704adc5ba1a479c07d47692b70ed3d2c5110f22d878342c9f130cbc3f6880baf242a7e0dd910406fbf3ef7042ae7c0048e22962378a6f77559a814c14589b800f8e85b0453c59df2b556dde6d97b349be203d96f3de1b08ec516f8822d2234d80e414e10544bd675728129b47430c6a97a6c5a7d63cbc6b05943db7995f5fbb8780ad9821a7d9a8dc8edca1c04e54694b8b6e9eac79ccf5cd52fbdfbc44dd40bb6180aac43c4819dfc8076857bc4207df0728ff8718ff5643b8d114db3cff83db6e62800aa81235e9b476c078c6c84b87498ed08f68db32a039f67811b3e8c14775a34f80ba7052563c97b91cccc3a3762e0a8d73a0fd2018bd63932fdf6e6dfb8e998705802a861f1d1699549a05c7c3073d5398e948b7ed4d1350a45e05a4b339b6ebe2ac8091188f5e6b7c3c7ad6e07e9fe3257e06da33cf5c39b20ee649c532503f7559df80974da04ec2f2a432413995b1c30d9903e6c69b63d25ea3564c3fd604513c045480cb8e86fd4e7f2fd7d521de7a4a4cbb7b0a7f05a7cbc93ba049ae2b46828e45ae35037f0006de3d8a54d27e44a9d5ce189618f22db4b49d95320d9021994c850f25b8e385a50200005000008000000800000000200000000400000500000005000000580200002c010000000020030004000000286bee0000000004000000040000000500000000000000000000000000000000000000000000000000000000000000000000000800000000200000040000000400000000040000b004000000000000000000001400000004000000040000000000000000000000000a00000000000000000000000000000000000000f49e207f03cfdce586301014700e2c25930041585f078d434d6125b40443fe11fd292d13a410000008004c5f0ec2d17a76153ff51817f12d9cfc3c7f04001501802100800141ae08db3446b1d71f36c83b4e840817ae553d816a1134a8c206c69026df2a80f2ce141c02c934f343545350b70e54c8c2a0bb12f886462797399672b145ff0c9901801804806d8032309590a0d9476546c43094b4b94f2237e8e67a52af89716a59953d379480aebb1dfa081e0f528a33c48cc0d64717ff2e6de6f73e001bc0c608d24f5b79b7802b35dd68944f8bc169d854a45ef1267991460df70f2e61815d84b719a968b53fa9019e0da05ca59913bc38a8630590f2627c0141808fddb9ddcad95600d1f5b3049f95a5bac21937cf27184955e4886b3d76a2267e585f078d434d6125b40443fe11fd292d13a410000008007c7700e67da63472835bb0b737093a19ad4cb6ff6f7d467b87a9e803000004005c040c00be373fc7be685e9a4ab00dd665dae5c553489add
# node panic....
As you can see those are continuous blocks.
However the Storage value for 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add is set to 3c000000 (line 4) but is retrieved as value 28000000 (line 13) without having been modified in between.
Notice that the value was taken from the shared cache (line 12)
Here are the logs (same filters) from the node that was able to process that block:
1. 2021-01-22 18:00:55.979 TRACE tokio-runtime-worker state:d8dd: Call Core_execute_block at Block Some(0x83b150af1b471cbd664c7d078d05524e61937c8bb173b3e5d435c79f45a7a887). Input=83b150af1b471cbd664c7d078d05524e61937c8bb173b3e5d435c79f45a7a887817b0149973bc34ac54b39c1ced7440440487c1e70e5144e7d4ff3d83dc5d1d5eee4a1ba0c01925b486e159eaf525949219bc85cd580b85614b09ac17f2ea2a24c4c08046175746850be373fc7be685e9a4ab00dd665dae5c553489add0466726f6e880128a548e6a5c19b3869aa096c0c820d649021c1fbc10785a75a788cb7c6791766000c280401000b5294412b7701bd130405029502382b6b5eaeaad15973c11879ef56e13a9967d100f9b52dd1308ed2751eee31767d7bd39dcd23d53fe794d07221a0a7c6f7eda8e261e9189f8d3e3a02af177df0bc2f61f60cc0ae0b718f6e0e45221f5bce53079277635b523e7bd96e3443dce6f95d08046175746850be373fc7be685e9a4ab00dd665dae5c553489add0466726f6e8801715d8cbb30c6ad6abb4e2ebf3e38caa61a5a7dcf49cfd0f669d19bed5d4cddd800b03f0000f39c2312aacc9dcb0d9d8a4df4b6d46097c8c7b5cc5fe2c5b56aeb2e139717930000000000000000000000000000000000000000000000000000000000000000000000200300005000008000000000000000000000000000000000000001dc4000000000000018f49e207f03cfdce586301014700e2c25930041585f078d434d6125b40443fe11fd292d13a410000008004c5f0ec2d17a76153ff51817f12d9cfc3c7f0400c106807ff6802ca40549562ffe6b52b99b82732a11693a9f94e719eb6091a28361553b7e1d6f8016120a954e0f8fc685a2b0a14b633f49e27e1268273f5f2d4b881d58b510f4db80837899b465dc8b2bc6e1c8ea078e124852dfdf7cd478d549d60dfd2e4867e76d80f0e739e245e4602295e1f12ac5d0f22b1d7a599772906194f38da563d749b95280e414e10544bd675728129b47430c6a97a6c5a7d63cbc6b05943db7995f5fbb8780ad9821a7d9a8dc8edca1c04e54694b8b6e9eac79ccf5cd52fbdfbc44dd40bb61806ece38b4bc81ae7502f2fefc79d81b92bf5a1e33c8f06928b6bb464266cabe12800aa81235e9b476c078c6c84b87498ed08f68db32a039f67811b3e8c14775a34f80ba7052563c97b91cccc3a3762e0a8d73a0fd2018bd63932fdf6e6dfb8e99870580f53f4d040f482565f713cacd84e1c23c45b7aa0979b2500e112c9f5ccab644318091188f5e6b7c3c7ad6e07e9fe3257e06da33cf5c39b20ee649c532503f7559df80974da04ec2f2a432413995b1c30d9903e6c69b63d25ea3564c3fd604513c045480036a41022c18eae5b4b1dd688de06a91e7eec5cbd9070dae6f93a4df1cd5618635037f0006de3d8a54d27e44a9d5ce189618f22db4b49d95320d9021994c850f25b8e385a50200005000008000000800000000200000000400000500000005000000580200002c010000000020030004000000286bee0000000004000000040000000500000000000000000000000000000000000000000000000000000000000000000000000800000000200000040000000400000000040000b004000000000000000000001400000004000000040000000000000000000000000a00000000000000000000000000000000000000a9019e0da05ca59913bc38a8630590f2627c014180ea1b6ee9e85ed26601a6b3d231a5fd858dbae91339c1ec636b48b04a50c49537585f078d434d6125b40443fe11fd292d13a410000008007c7700e67da63472835bb0b737093a19ad4cb6ff6f7d467b87a9e80300000400150180210080485c9030f38b1203d2249210673d214762e89fffe6d6c23e2c02dc8ab38feb9180f2ce141c02c934f343545350b70e54c8c2a0bb12f886462797399672b145ff0c9901801804806d8032309590a0d9476546c43094b4b94f2237e8e67a52af89716a59953d379480aebb1dfa081e0f528a33c48cc0d64717ff2e6de6f73e001bc0c608d24f5b79b78005dcbc38e4827511881a54616f9e17405237f8b14edaeb53f19ca9d4280d28215c040c00be373fc7be685e9a4ab00dd665dae5c553489add
2. 2021-01-22 18:00:55.982 TRACE tokio-runtime-worker sc_client_db::storage_cache:Cache lookup skipped for 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add: modified in a later block
3. 2021-01-22 18:00:55.982 TRACE tokio-runtime-worker sc_client_db::storage_cache:Cache miss: 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add
4. 2021-01-22 18:00:55.982 TRACE tokio-runtime-worker state:d8dd: Get 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add=Some(28000000) # valid key for account 0x.....89add
5. 2021-01-22 18:00:55.982 TRACE tokio-runtime-worker state:d8dd: Put 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add=Some(3c000000)
6. 2021-01-22 18:00:55.996 DEBUG tokio-runtime-worker db:DB Commit 0xd0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685 (7904), best = false
7. 2021-01-22 18:01:06.679 DEBUG tokio-runtime-worker db:DB Commit 0xd0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685 (7904), best = true
8. 2021-01-22 18:01:07.992 TRACE tokio-runtime-worker state:41f7: Call Core_execute_block at Block Some(0xd0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685). Input=d0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685857b1bf62274828cc0f601591107d246f10936f625814ba03ae2d3c2dc5788fe9710cb1c8108a3fdc301f41afd3a89f9cfff7d3def434c65b49845bd0192cd1c4c6e0804617574685005160bacc74e6af4d755f9dd6d409fc99ee918fa0466726f6e88010267806f0d0e51de91c5e0a8eb630a66d7e89a5f042fb68a781afda2fb07c8dc000c280401000b0ac3412b7701bd13040502950283b150af1b471cbd664c7d078d05524e61937c8bb173b3e5d435c79f45a7a887817b0149973bc34ac54b39c1ced7440440487c1e70e5144e7d4ff3d83dc5d1d5eee4a1ba0c01925b486e159eaf525949219bc85cd580b85614b09ac17f2ea2a24c4c08046175746850be373fc7be685e9a4ab00dd665dae5c553489add0466726f6e880128a548e6a5c19b3869aa096c0c820d649021c1fbc10785a75a788cb7c679176600b23f0000d581131ca0a90781203d1fd2b7ac91ee8c4ef07a0cabed12c7c8940bb2c6cba70000000000000000000000000000000000000000000000000000000000000000000000200300005000008000000000000000000000000000000000000001de40000000000000189901801804806d8032309590a0d9476546c43094b4b94f2237e8e67a52af89716a59953d379480aebb1dfa081e0f528a33c48cc0d64717ff2e6de6f73e001bc0c608d24f5b79b78010809b7c3d133876803f5891b48cbff4a48585d529f32b86af570c86680117a7a9019e0da05ca59913bc38a8630590f2627c0141805beb60d8935cbdf1529b2119521df93f0ca1a4f84349cf1ced38401e5907b3f5585f078d434d6125b40443fe11fd292d13a410000008007c7700e67da63472835bb0b737093a19ad4cb6ff6f7d467b87a9e8030000040035037f0006de3d8a54d27e44a9d5ce189618f22db4b49d95320d9021994c850f25b8e385a50200005000008000000800000000200000000400000500000005000000580200002c010000000020030004000000286bee0000000004000000040000000500000000000000000000000000000000000000000000000000000000000000000000000800000000200000040000000400000000040000b004000000000000000000001400000004000000040000000000000000000000000a00000000000000000000000000000000000000150180210080a6a5805cd127cecb9decc694386b416b76567697e1094bac14e718929179076680f2ce141c02c934f343545350b70e54c8c2a0bb12f886462797399672b145ff0cf49e207f03cfdce586301014700e2c25930041585f078d434d6125b40443fe11fd292d13a410000008004c5f0ec2d17a76153ff51817f12d9cfc3c7f0400c106807ff6802ca40549562ffe6b52b99b82732a11693a9f94e719eb6091a28361553b7e1d6f80e40aec7f2b9ca3a8fa0952bb2898b94b1f5e7a4b1d713e5e8844b588b152d1c0804451323afe908224fd96ab1a2ba76ef3ee9d1b7ab81e04b0605d103912feb2f98057af15b60ec853bab744e556ba4b2fef2d3a9dcd6038e7a3f078294e3e239c1980e414e10544bd675728129b47430c6a97a6c5a7d63cbc6b05943db7995f5fbb8780ad9821a7d9a8dc8edca1c04e54694b8b6e9eac79ccf5cd52fbdfbc44dd40bb61809f684e900656c53b05aef9dbe921006ee18dd942177e060d9da16bf1f055a3c3800aa81235e9b476c078c6c84b87498ed08f68db32a039f67811b3e8c14775a34f80ba7052563c97b91cccc3a3762e0a8d73a0fd2018bd63932fdf6e6dfb8e998705801ff6bd8cc8c437422dfcd3436f3a64b91b0299840bf037a2cb65fe538ef7a6ea8091188f5e6b7c3c7ad6e07e9fe3257e06da33cf5c39b20ee649c532503f7559df80974da04ec2f2a432413995b1c30d9903e6c69b63d25ea3564c3fd604513c045480cc4045551a5a410e1cbf235d9d7a1eafa40201cd7bea87351747fadfa4d6afa55c040c0005160bacc74e6af4d755f9dd6d409fc99ee918fa
9. 2021-01-22 18:01:07.997 TRACE tokio-runtime-worker sc_client_db::storage_cache:Cache lookup skipped for 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000296e8cd9add026bf61c4f754972ac20605160bacc74e6af4d755f9dd6d409fc99ee918fa: modified in a later block
10. 2021-01-22 18:01:07.997 TRACE tokio-runtime-worker sc_client_db::storage_cache:Cache miss: 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000296e8cd9add026bf61c4f754972ac20605160bacc74e6af4d755f9dd6d409fc99ee918fa
11. 2021-01-22 18:01:07.997 TRACE tokio-runtime-worker state:41f7: Get 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000296e8cd9add026bf61c4f754972ac20605160bacc74e6af4d755f9dd6d409fc99ee918fa=Some(14000000) # this is a different key (account 0x......918fa)
12. 2021-01-22 18:01:07.997 TRACE tokio-runtime-worker state:41f7: Put 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000296e8cd9add026bf61c4f754972ac20605160bacc74e6af4d755f9dd6d409fc99ee918fa=Some(28000000) # this is a different key (account 0x......918fa)
13. 2021-01-22 18:01:08.021 DEBUG tokio-runtime-worker db:DB Commit 0xd44215f3f482eec3f8326a9621f1954f68fc857829e33ec2a0dac67a44dc9ac5 (7905), best = false
14. 2021-01-22 18:01:18.665 DEBUG tokio-runtime-worker db:DB Commit 0xd44215f3f482eec3f8326a9621f1954f68fc857829e33ec2a0dac67a44dc9ac5 (7905), best = true
15. 2021-01-22 18:01:20.093 TRACE tokio-runtime-worker state:6a9b: Call Core_execute_block at Block Some(0xd44215f3f482eec3f8326a9621f1954f68fc857829e33ec2a0dac67a44dc9ac5). Input=d44215f3f482eec3f8326a9621f1954f68fc857829e33ec2a0dac67a44dc9ac5897b9204c82355aaafdcaf52f041214bc49f94c16a00f6ca9850bd18f2cdd3da4d978f11e22194b4518a529ebd0a39f58e0ecd54b2ecd29f2dd1bf9039f72ed13c1108046175746850be373fc7be685e9a4ab00dd665dae5c553489add0466726f6e8801af97ca9131cc8f4bfc5020f298594a6491d0d55bdbd6f5f0b2e479743d537f6d000c280401000be9f1412b7701bd130405029502d0fb8c5274ef0a6e3a03bb9d48fce57b4bf4d8d783733a368705b30e93b98685857b1bf62274828cc0f601591107d246f10936f625814ba03ae2d3c2dc5788fe9710cb1c8108a3fdc301f41afd3a89f9cfff7d3def434c65b49845bd0192cd1c4c6e0804617574685005160bacc74e6af4d755f9dd6d409fc99ee918fa0466726f6e88010267806f0d0e51de91c5e0a8eb630a66d7e89a5f042fb68a781afda2fb07c8dc00b43f000014c3635523f765d4d0a341f20755c5a3b16f2b2a239b8a4fe6e4ea00c9293bf40000000000000000000000000000000000000000000000000000000000000000000000200300005000008000000000000000000000000000000000000001e04000000000000018c106807ff6802ca40549562ffe6b52b99b82732a11693a9f94e719eb6091a28361553b7e1d6f807cc87704adc5ba1a479c07d47692b70ed3d2c5110f22d878342c9f130cbc3f6880baf242a7e0dd910406fbf3ef7042ae7c0048e22962378a6f77559a814c14589b800f8e85b0453c59df2b556dde6d97b349be203d96f3de1b08ec516f8822d2234d80e414e10544bd675728129b47430c6a97a6c5a7d63cbc6b05943db7995f5fbb8780ad9821a7d9a8dc8edca1c04e54694b8b6e9eac79ccf5cd52fbdfbc44dd40bb6180aac43c4819dfc8076857bc4207df0728ff8718ff5643b8d114db3cff83db6e62800aa81235e9b476c078c6c84b87498ed08f68db32a039f67811b3e8c14775a34f80ba7052563c97b91cccc3a3762e0a8d73a0fd2018bd63932fdf6e6dfb8e998705802a861f1d1699549a05c7c3073d5398e948b7ed4d1350a45e05a4b339b6ebe2ac8091188f5e6b7c3c7ad6e07e9fe3257e06da33cf5c39b20ee649c532503f7559df80974da04ec2f2a432413995b1c30d9903e6c69b63d25ea3564c3fd604513c045480cb8e86fd4e7f2fd7d521de7a4a4cbb7b0a7f05a7cbc93ba049ae2b46828e45ae35037f0006de3d8a54d27e44a9d5ce189618f22db4b49d95320d9021994c850f25b8e385a50200005000008000000800000000200000000400000500000005000000580200002c010000000020030004000000286bee0000000004000000040000000500000000000000000000000000000000000000000000000000000000000000000000000800000000200000040000000400000000040000b004000000000000000000001400000004000000040000000000000000000000000a00000000000000000000000000000000000000f49e207f03cfdce586301014700e2c25930041585f078d434d6125b40443fe11fd292d13a410000008004c5f0ec2d17a76153ff51817f12d9cfc3c7f04001501802100800141ae08db3446b1d71f36c83b4e840817ae553d816a1134a8c206c69026df2a80f2ce141c02c934f343545350b70e54c8c2a0bb12f886462797399672b145ff0c9901801804806d8032309590a0d9476546c43094b4b94f2237e8e67a52af89716a59953d379480aebb1dfa081e0f528a33c48cc0d64717ff2e6de6f73e001bc0c608d24f5b79b7802b35dd68944f8bc169d854a45ef1267991460df70f2e61815d84b719a968b53fa9019e0da05ca59913bc38a8630590f2627c0141808fddb9ddcad95600d1f5b3049f95a5bac21937cf27184955e4886b3d76a2267e585f078d434d6125b40443fe11fd292d13a410000008007c7700e67da63472835bb0b737093a19ad4cb6ff6f7d467b87a9e803000004005c040c00be373fc7be685e9a4ab00dd665dae5c553489add
16. 2021-01-22 18:01:20.101 TRACE tokio-runtime-worker sc_client_db::storage_cache:Cache lookup skipped for 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add: modified in a later block
17. 2021-01-22 18:01:20.101 TRACE tokio-runtime-worker sc_client_db::storage_cache:Cache miss: 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add
18. 2021-01-22 18:01:20.101 TRACE tokio-runtime-worker state:6a9b: Get 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add=Some(3c000000) # RIGHT VALUE for account 0x.....89add
19. 2021-01-22 18:01:20.101 TRACE tokio-runtime-worker state:6a9b: Put 22fbe0bd0cb77b6b6f365f641b0de381657601709915d07919ad0a0320b505aaa3848df8b17be9c8185ec170c497b8ac8c010000c140174ab394e42a10c473ea67af83c0be373fc7be685e9a4ab00dd665dae5c553489add=Some(50000000)
20. 2021-01-22 18:01:20.135 DEBUG tokio-runtime-worker db:DB Commit 0x05e998f60a8d6b18e1e4bfae235f0cdeefb0f52850456060d487b8214bac9430 (7906), best = false
# all good
The blocks are the same as the previous one, but this time the cache is skipped (line 16) (not sure why it behaves differently in this scenario) and the value retrieve for the storage key is the valid one (line 18)
One possible hypothesis: The cache was not skipped because the node received the block in a batch (or because it received them after a long time).
If you look at the timestamp, the failing long processed the 2 last blocks after (because of connectivity issue). It received the block in a batch as seen in those log line:
This log line is visible:
2021-01-22 13:07:07.795 TRACE tokio-runtime-worker sync:Scheduling 31 blocks for import
2021-01-22 13:07:07.795 TRACE tokio-runtime-worker sync:Starting import of 31 blocks (7905..7935)