Mining aborted due to sync

[rewrewby]

Hi there,

System information

Geth version: v1.11.16 unstable commit a3b5c762376c8ceec388d238d293c9ef76bd6549
OS & Version: Linux Ubuntu 16.04
Commit hash : a3b5c76

Expected behaviour

Mining without interrupt

Actual behaviour

Mining aborted due to sync messages almost every 1-3 blocks. And seems to miner stops to mine during this "fake sync":

core-geth/miner/miner.go

Line 105 in a3b5c76

miner.worker.stop()

Steps to reproduce the behaviour

Update core-geth to v1.11.16 unstable commit a3b5c76

Log (part of)

...
INFO [10-09|19:43:19.812] Commit new mining work                   number=11369674 sealhash="d9f993…b8446b" uncles=0 txs=0  gas=0       fees=0               elapsed="297.322µs"
INFO [10-09|19:43:21.736] Successfully sealed new block            number=11369674 sealhash="d9f993…b8446b" hash="515b42…9786f3" elapsed=1.924s
INFO [10-09|19:43:21.737] 🔨 mined potential block                  number=11369674 hash="515b42…9786f3"
INFO [10-09|19:43:21.737] Commit new mining work                   number=11369675 sealhash="9615e4…0d7717" uncles=0 txs=0  gas=0       fees=0               elapsed="374.843µs"
INFO [10-09|19:43:21.738] Commit new mining work                   number=11369675 sealhash="80c5fd…51c1f0" uncles=0 txs=1  gas=21000   fees=0.000147        elapsed=1.866ms
INFO [10-09|19:43:25.164] Imported new chain segment               blocks=1  txs=1  mgas=0.021 elapsed=8.378ms     mgasps=2.506  number=11369675 hash="dcfb4c…23ec5a" dirty=2.88MiB
INFO [10-09|19:43:25.164] Commit new mining work                   number=11369676 sealhash="2e561b…8f94f1" uncles=0 txs=0  gas=0       fees=0               elapsed="526.677µs"
INFO [10-09|19:43:43.715] Imported new chain segment               blocks=1  txs=1  mgas=0.046 elapsed=7.866ms     mgasps=5.790  number=11369676 hash="764410…711f8a" dirty=2.89MiB
INFO [10-09|19:43:43.716] Commit new mining work                   number=11369677 sealhash="9b70f9…c5c1bf" uncles=0 txs=0  gas=0       fees=0               elapsed="483.05µs"
INFO [10-09|19:43:45.393] Deep froze chain segment                 blocks=8  elapsed=4.658ms     number=11279676 hash="70be8c…fb8b96"
INFO [10-09|19:43:47.747] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=7.913ms     mgasps=0.000  number=11369677 hash="a047a6…0f2ee0" dirty=2.84MiB
INFO [10-09|19:43:47.747] Commit new mining work                   number=11369678 sealhash="122270…b8fc4d" uncles=0 txs=0  gas=0       fees=0               elapsed="398.762µs"
INFO [10-09|19:43:48.944] Mining aborted due to sync 
WARN [10-09|19:43:48.965] Ancestor below allowance                 peer=29f5de3fa1a99a16 number=11279677 hash="000000…000000" allowance=11279677
WARN [10-09|19:43:48.965] Synchronisation failed, dropping peer    peer=29f5de3fa1a99a16 err="retrieved ancestor is invalid"
INFO [10-09|19:43:48.965] Commit new mining work                   number=11369678 sealhash="f05dc0…070dec" uncles=0 txs=0  gas=0       fees=0               elapsed="427.57µs"
INFO [10-09|19:43:48.967] Commit new mining work                   number=11369678 sealhash="694722…0bbdf4" uncles=0 txs=1  gas=45543   fees=0.000956403     elapsed=2.215ms
INFO [10-09|19:43:51.484] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=7.389ms     mgasps=0.000  number=11369678 hash="86f76d…7c6ab3" dirty=2.84MiB
INFO [10-09|19:43:51.484] Commit new mining work                   number=11369679 sealhash="60922e…978977" uncles=0 txs=0  gas=0       fees=0               elapsed="433.978µs"
INFO [10-09|19:43:51.486] Commit new mining work                   number=11369679 sealhash="40014a…40ed6b" uncles=0 txs=1  gas=45543   fees=0.000956403     elapsed=1.586ms
INFO [10-09|19:43:58.014] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=8.173ms     mgasps=0.000  number=11369679 hash="9f945a…e92d73" dirty=2.83MiB
INFO [10-09|19:43:58.014] Commit new mining work                   number=11369680 sealhash="b31823…d50d3e" uncles=0 txs=0  gas=0       fees=0               elapsed="374.926µs"
INFO [10-09|19:43:58.017] Commit new mining work                   number=11369680 sealhash="1ef335…54eae2" uncles=0 txs=3  gas=112086  fees=0.002752806     elapsed=3.534ms
INFO [10-09|19:44:03.263] Imported new chain segment               blocks=1  txs=3  mgas=0.112 elapsed=9.946ms     mgasps=11.269 number=11369680 hash="f878fd…a5565d" dirty=2.83MiB
INFO [10-09|19:44:03.264] Commit new mining work                   number=11369681 sealhash="d6013f…b0deca" uncles=0 txs=0  gas=0       fees=0               elapsed="402.923µs"
INFO [10-09|19:44:06.660] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=4.355ms     mgasps=0.000  number=11369681 hash="40c305…bc3f3c" dirty=2.83MiB
INFO [10-09|19:44:06.661] 🔗 block reached canonical chain          number=11369674 hash="515b42…9786f3"
INFO [10-09|19:44:06.661] Commit new mining work                   number=11369682 sealhash="065e91…0e6d48" uncles=0 txs=0  gas=0       fees=0               elapsed="629.318µs"
INFO [10-09|19:44:06.662] Commit new mining work                   number=11369682 sealhash="a83adf…fd10dc" uncles=0 txs=1  gas=21000   fees=0.00015435      elapsed=1.792ms
INFO [10-09|19:44:07.527] Imported new chain segment               blocks=1  txs=1  mgas=0.021 elapsed=9.108ms     mgasps=2.306  number=11369682 hash="3721e5…844216" dirty=2.80MiB
INFO [10-09|19:44:07.527] Commit new mining work                   number=11369683 sealhash="c958e0…9e246a" uncles=0 txs=0  gas=0       fees=0               elapsed="386.514µs"
INFO [10-09|19:44:10.495] Mining aborted due to sync 
WARN [10-09|19:44:10.509] Ancestor below allowance                 peer=f1042c3a8e77fb0f number=11279682 hash="000000…000000" allowance=11279682
WARN [10-09|19:44:10.509] Synchronisation failed, dropping peer    peer=f1042c3a8e77fb0f err="retrieved ancestor is invalid"
INFO [10-09|19:44:10.509] Commit new mining work                   number=11369683 sealhash="150a88…cce2fd" uncles=0 txs=0  gas=0       fees=0               elapsed="385.845µs"
INFO [10-09|19:44:17.838] Mining aborted due to sync 
WARN [10-09|19:44:18.130] Ancestor below allowance                 peer=f94c1e467b068641 number=11279682 hash="000000…000000" allowance=11279682
WARN [10-09|19:44:18.130] Synchronisation failed, dropping peer    peer=f94c1e467b068641 err="retrieved ancestor is invalid"
INFO [10-09|19:44:18.131] Commit new mining work                   number=11369683 sealhash="62006f…c5b332" uncles=0 txs=0  gas=0       fees=0               elapsed="311.691µs"
INFO [10-09|19:44:18.132] Commit new mining work                   number=11369683 sealhash="6db730…e44132" uncles=0 txs=2  gas=66543   fees=0.001061403     elapsed=1.636ms
INFO [10-09|19:44:20.005] Mining aborted due to sync 
WARN [10-09|19:44:20.275] Synchronisation failed, dropping peer    peer=0f93d4e24ef77190 err="action from bad peer ignored: returned headers 0 != requested 1"
INFO [10-09|19:44:20.276] Commit new mining work                   number=11369683 sealhash="1dc753…0b3eb2" uncles=0 txs=0  gas=0       fees=0               elapsed="323.875µs"
INFO [10-09|19:44:20.279] Commit new mining work                   number=11369683 sealhash="6fd55c…d205ac" uncles=0 txs=3  gas=87543   fees=0.001481403     elapsed=3.487ms
INFO [10-09|19:44:24.067] Mining aborted due to sync 
WARN [10-09|19:44:24.334] Ancestor below allowance                 peer=409245f0aee1c1bd number=11279682 hash="000000…000000" allowance=11279682
WARN [10-09|19:44:24.334] Synchronisation failed, dropping peer    peer=409245f0aee1c1bd err="retrieved ancestor is invalid"
INFO [10-09|19:44:24.335] Commit new mining work                   number=11369683 sealhash="49c197…fcd49b" uncles=0 txs=0  gas=0       fees=0               elapsed="475.255µs"
INFO [10-09|19:44:24.337] Commit new mining work                   number=11369683 sealhash="2c1b54…381205" uncles=0 txs=3  gas=87543   fees=0.001481403     elapsed=2.688ms
INFO [10-09|19:44:27.702] Mining aborted due to sync 
WARN [10-09|19:44:27.730] Ancestor below allowance                 peer=3c298e40030c81e3 number=11279682 hash="000000…000000" allowance=11279682
WARN [10-09|19:44:27.730] Synchronisation failed, dropping peer    peer=3c298e40030c81e3 err="retrieved ancestor is invalid"
INFO [10-09|19:44:27.730] Commit new mining work                   number=11369683 sealhash="7bcf4d…e5f1cb" uncles=0 txs=0  gas=0       fees=0               elapsed="307.126µs"
INFO [10-09|19:44:27.732] Commit new mining work                   number=11369683 sealhash="776c2b…d483f7" uncles=0 txs=4  gas=133086  fees=0.002437806     elapsed=1.687ms
INFO [10-09|19:44:37.587] Mining aborted due to sync 
WARN [10-09|19:44:37.594] Ancestor below allowance                 peer=ec015446019e65ad number=11279682 hash="000000…000000" allowance=11279682
WARN [10-09|19:44:37.594] Synchronisation failed, dropping peer    peer=ec015446019e65ad err="retrieved ancestor is invalid"
ERROR[10-09|19:44:37.594] Failed to unregister sync peer           peer=ec015446019e65ad err="peer is not registered"
ERROR[10-09|19:44:37.594] Peer removal failed                      peer=ec015446019e65ad err="peer is not registered"
INFO [10-09|19:44:37.594] Commit new mining work                   number=11369683 sealhash="0c38b5…8bf952" uncles=0 txs=0  gas=0       fees=0               elapsed="406.162µs"
INFO [10-09|19:44:37.597] Commit new mining work                   number=11369683 sealhash="307e58…b7e3b0" uncles=0 txs=5  gas=178629  fees=0.003394209     elapsed=2.826ms
INFO [10-09|19:44:43.598] Imported new chain segment               blocks=1  txs=5  mgas=0.179 elapsed=9.302ms     mgasps=19.203 number=11369683 hash="b22710…17d688" dirty=2.83MiB
INFO [10-09|19:44:43.598] Commit new mining work                   number=11369684 sealhash="a547d1…c0dba3" uncles=0 txs=0  gas=0       fees=0               elapsed="421.331µs"
INFO [10-09|19:44:45.397] Deep froze chain segment                 blocks=7  elapsed=3.824ms     number=11279683 hash="adf0fb…2d08cd"
INFO [10-09|19:44:55.843] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=7.354ms     mgasps=0.000  number=11369684 hash="8d6522…62e665" dirty=2.82MiB
INFO [10-09|19:44:55.843] Commit new mining work                   number=11369685 sealhash="d9579c…b7e257" uncles=0 txs=0  gas=0       fees=0               elapsed="355.358µs"
INFO [10-09|19:44:56.791] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=9.260ms     mgasps=0.000  number=11369685 hash="94714e…70e1f8" dirty=2.82MiB
INFO [10-09|19:44:56.791] Commit new mining work                   number=11369686 sealhash="2e5993…0b02d6" uncles=0 txs=0  gas=0       fees=0               elapsed="299.748µs"
INFO [10-09|19:45:01.188] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=9.662ms     mgasps=0.000  number=11369686 hash="70b187…0604e7" dirty=2.77MiB
INFO [10-09|19:45:01.189] Commit new mining work                   number=11369687 sealhash="eca08c…8b3b7a" uncles=0 txs=0  gas=0       fees=0               elapsed="539.169µs"
INFO [10-09|19:45:02.131] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=8.848ms     mgasps=0.000  number=11369687 hash="7dbb51…b9cdf9" dirty=2.76MiB
INFO [10-09|19:45:02.133] Commit new mining work                   number=11369688 sealhash="9aabca…03a9e5" uncles=0 txs=0  gas=0       fees=0               elapsed="814.011µs"
INFO [10-09|19:45:02.133] Commit new mining work                   number=11369688 sealhash="7d12ec…a95117" uncles=0 txs=1  gas=22024   fees=0.00066072      elapsed=1.584ms
INFO [10-09|19:45:15.618] Imported new chain segment               blocks=1  txs=20 mgas=0.421 elapsed=15.328ms    mgasps=27.468 number=11369688 hash="bac177…33a9ae" dirty=2.83MiB
INFO [10-09|19:45:15.618] Commit new mining work                   number=11369689 sealhash="d7f577…fe5ec9" uncles=0 txs=0  gas=0       fees=0               elapsed="641.655µs"
INFO [10-09|19:45:15.620] Commit new mining work                   number=11369689 sealhash="109fd1…a451af" uncles=0 txs=1  gas=21000   fees=2.1e-05         elapsed=2.067ms
INFO [10-09|19:45:28.725] Imported new chain segment               blocks=1  txs=1  mgas=0.021 elapsed=10.554ms    mgasps=1.990  number=11369689 hash="6f42b7…5641ba" dirty=2.82MiB
INFO [10-09|19:45:28.725] Commit new mining work                   number=11369690 sealhash="797855…f2c4b8" uncles=0 txs=0  gas=0       fees=0               elapsed="304.583µs"
ERROR[10-09|19:45:37.025] Failed to unregister sync peer           peer=6fd967a5ca380c3c err="peer is not registered"
ERROR[10-09|19:45:37.025] Peer removal failed                      peer=6fd967a5ca380c3c err="peer is not registered"
INFO [10-09|19:45:39.438] Successfully sealed new block            number=11369690 sealhash="797855…f2c4b8" hash="6c637d…20cf8c" elapsed=10.712s
INFO [10-09|19:45:39.438] 🔨 mined potential block                  number=11369690 hash="6c637d…20cf8c"
INFO [10-09|19:45:39.438] Commit new mining work                   number=11369691 sealhash="34f44b…941ab0" uncles=0 txs=0  gas=0       fees=0               elapsed="469.388µs"
INFO [10-09|19:45:39.439] Commit new mining work                   number=11369691 sealhash="fcda41…335d3e" uncles=0 txs=1  gas=21000   fees=6.3e-05         elapsed=1.426ms
INFO [10-09|19:45:40.082] Successfully sealed new block            number=11369691 sealhash="fcda41…335d3e" hash="bb0656…f14c65" elapsed=642.155ms
INFO [10-09|19:45:40.082] 🔨 mined potential block                  number=11369691 hash="bb0656…f14c65"
INFO [10-09|19:45:40.082] Commit new mining work                   number=11369692 sealhash="3467b8…749885" uncles=0 txs=0  gas=0       fees=0               elapsed="419.351µs"
INFO [10-09|19:45:41.279] Mining aborted due to sync 
WARN [10-09|19:45:41.312] Ancestor below allowance                 peer=29f5de3fa1a99a16 number=11279691 hash="000000…000000" allowance=11279691
WARN [10-09|19:45:41.312] Synchronisation failed, dropping peer    peer=29f5de3fa1a99a16 err="retrieved ancestor is invalid"
INFO [10-09|19:45:41.312] Commit new mining work                   number=11369692 sealhash="210b75…540b48" uncles=0 txs=0  gas=0       fees=0               elapsed="439.444µs"
INFO [10-09|19:45:45.401] Deep froze chain segment                 blocks=8  elapsed=3.635ms     number=11279691 hash="ab0c8a…4e7801"
INFO [10-09|19:46:08.264] Imported new chain segment               blocks=1  txs=1  mgas=0.021 elapsed=9.844ms     mgasps=2.133  number=11369692 hash="d0240f…86b797" dirty=2.83MiB
INFO [10-09|19:46:08.265] Commit new mining work                   number=11369693 sealhash="165843…b0164c" uncles=0 txs=0  gas=0       fees=0               elapsed="398.951µs"
INFO [10-09|19:46:11.875] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=10.730ms    mgasps=0.000  number=11369693 hash="e50101…a11e9b" dirty=2.80MiB
INFO [10-09|19:46:11.876] Commit new mining work                   number=11369694 sealhash="c3d9c7…3ea8e0" uncles=0 txs=0  gas=0       fees=0               elapsed="402.823µs"
WARN [10-09|19:46:16.380] Synchronisation failed, retrying         err="peer is unknown or unhealthy"
INFO [10-09|19:46:19.770] Imported new chain segment               blocks=1  txs=2  mgas=0.044 elapsed=8.720ms     mgasps=5.024  number=11369694 hash="63a1d7…757686" dirty=2.79MiB
INFO [10-09|19:46:19.771] Commit new mining work                   number=11369695 sealhash="053a77…0a0728" uncles=0 txs=0  gas=0       fees=0               elapsed="883.376µs"
INFO [10-09|19:46:30.919] Successfully sealed new block            number=11369695 sealhash="053a77…0a0728" hash="7a4398…0616e9" elapsed=11.147s
INFO [10-09|19:46:30.919] 🔨 mined potential block                  number=11369695 hash="7a4398…0616e9"
INFO [10-09|19:46:30.920] Commit new mining work                   number=11369696 sealhash="156290…0994ba" uncles=0 txs=0  gas=0       fees=0               elapsed="697.25µs"
INFO [10-09|19:46:30.921] Commit new mining work                   number=11369696 sealhash="992f07…294f4b" uncles=0 txs=1  gas=21000   fees=0.00015435      elapsed=1.943ms
INFO [10-09|19:46:35.796] Imported new chain segment               blocks=1  txs=1  mgas=0.021 elapsed=6.516ms     mgasps=3.222  number=11369696 hash="783eeb…0f3b98" dirty=2.77MiB
INFO [10-09|19:46:35.797] Commit new mining work                   number=11369697 sealhash="3f67d4…e33374" uncles=0 txs=0  gas=0       fees=0               elapsed="609.4µs"
INFO [10-09|19:46:37.293] Mining aborted due to sync 
WARN [10-09|19:46:37.879] Ancestor below allowance                 peer=5a373cf9723ba375 number=11279696 hash="000000…000000" allowance=11279696
WARN [10-09|19:46:37.879] Synchronisation failed, dropping peer    peer=5a373cf9723ba375 err="retrieved ancestor is invalid"
INFO [10-09|19:46:37.880] Commit new mining work                   number=11369697 sealhash="2cd920…75b9cf" uncles=0 txs=0  gas=0       fees=0               elapsed="590.484µs"
INFO [10-09|19:46:38.089] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=8.508ms     mgasps=0.000  number=11369697 hash="8c1ad0…e363f5" dirty=2.76MiB
INFO [10-09|19:46:38.090] 🔗 block reached canonical chain          number=11369690 hash="6c637d…20cf8c"
INFO [10-09|19:46:38.090] Commit new mining work                   number=11369698 sealhash="5e1bae…aa5ecd" uncles=0 txs=0  gas=0       fees=0               elapsed="448.296µs"
INFO [10-09|19:46:45.409] Deep froze chain segment                 blocks=6  elapsed=7.414ms     number=11279697 hash="1030d4…4184a9"
INFO [10-09|19:46:52.091] Commit new mining work                   number=11369698 sealhash="c28e15…1a3ed3" uncles=0 txs=1  gas=45543   fees=0.000956403     elapsed=1.595ms
INFO [10-09|19:46:55.624] Imported new chain segment               blocks=1  txs=1  mgas=0.046 elapsed=10.416ms    mgasps=4.372  number=11369698 hash="68ad11…e38c3b" dirty=2.77MiB
INFO [10-09|19:46:55.625] 🔗 block reached canonical chain          number=11369691 hash="bb0656…f14c65"
INFO [10-09|19:46:55.625] Commit new mining work                   number=11369699 sealhash="13b1f8…f1b67f" uncles=0 txs=0  gas=0       fees=0               elapsed="660.949µs"
INFO [10-09|19:47:03.723] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=8.546ms     mgasps=0.000  number=11369699 hash="706c69…59b61b" dirty=2.77MiB
INFO [10-09|19:47:03.724] Commit new mining work                   number=11369700 sealhash="279dbf…1e470f" uncles=0 txs=0  gas=0       fees=0               elapsed="410.446µs"
INFO [10-09|19:47:03.725] Commit new mining work                   number=11369700 sealhash="84d23e…a22ade" uncles=0 txs=2  gas=42000   fees=0.00046935      elapsed=1.678ms
INFO [10-09|19:47:16.780] Imported new chain segment               blocks=1  txs=3  mgas=0.063 elapsed=10.486ms    mgasps=6.008  number=11369700 hash="0dcf38…ecf9b9" dirty=2.78MiB
INFO [10-09|19:47:16.781] Commit new mining work                   number=11369701 sealhash="16b713…6ed8a5" uncles=0 txs=0  gas=0       fees=0               elapsed="381.418µs"
...

[rewrewby]

Another log's screenshot: node missed 5 (!!!) blocks!

[q9f]

Getting the same on Mordor testnet.

INFO [10-19|10:24:46.795] Commit new mining work                   number=2520000 sealhash="fbf66e…654af2" uncles=0 txs=0 gas=0     fees=0       elapsed="276.75µs"
INFO [10-19|10:24:46.796] Commit new mining work                   number=2520000 sealhash="08ce54…1e0bcc" uncles=0 txs=1 gas=21000 fees=2.1e-05 elapsed=1.077ms
INFO [10-19|10:24:47.745] Mining aborted due to sync 

I'm not sure how to mine a valid block.

[meowsbits]

This issue is resolved on master.

Since your number=2520000 looks related to the ECIP1099 activation on Mordor, please open a new issue to that context.