Mining aborted due to sync

[slavserver]

System information

Geth version: 1,11,15
OS & Version: ubuntu

Mining aborted due to sync (150 peers)

[iquidus]

Can you please provide logs?

And what version did you update from?

[oneevil]

Confimred. Update from CoreGeth/v1.11.12-stable-5ff3eba6

178 peers online

Oct 02 18:26:05 asia-p1 getc[4115]: INFO [10-02|18:26:05.235] Commit new mining work                   number=11323669 sealhash="c4e05f…d721a9" uncles=0 txs=0  gas=0      fees=0               elapsed="174.466µs"
Oct 02 18:26:05 asia-p1 getc[4115]: INFO [10-02|18:26:05.236] Commit new mining work                   number=11323669 sealhash="38e008…c06860" uncles=0 txs=4  gas=139093 fees=0.002108368     elapsed=1.439ms
Oct 02 18:26:23 asia-p1 getc[4115]: INFO [10-02|18:26:23.117] Mining aborted due to sync
Oct 02 18:26:23 asia-p1 getc[4115]: WARN [10-02|18:26:23.184] Ancestor below allowance                 peer=50ada560c7e462a6 number=11233668 hash="000000…000000" allowance=11233668
Oct 02 18:26:23 asia-p1 getc[4115]: WARN [10-02|18:26:23.185] Synchronisation failed, dropping peer    peer=50ada560c7e462a6 err="retrieved ancestor is invalid"
Oct 02 18:26:23 asia-p1 getc[4115]: INFO [10-02|18:26:23.185] Commit new mining work                   number=11323669 sealhash="13e7bd…9d5f1c" uncles=0 txs=0  gas=0      fees=0               elapsed="236.773µs"
Oct 02 18:26:23 asia-p1 getc[4115]: INFO [10-02|18:26:23.187] Commit new mining work                   number=11323669 sealhash="d33dcd…075773" uncles=0 txs=4  gas=139093 fees=0.002108368     elapsed=2.049ms
Oct 02 18:26:24 asia-p1 getc[4115]: INFO [10-02|18:26:24.243] Mining aborted due to sync
Oct 02 18:26:24 asia-p1 getc[4115]: WARN [10-02|18:26:24.415] Ancestor below allowance                 peer=62624ff5a3abb031 number=11233668 hash="000000…000000" allowance=11233668
Oct 02 18:26:24 asia-p1 getc[4115]: WARN [10-02|18:26:24.415] Synchronisation failed, dropping peer    peer=62624ff5a3abb031 err="retrieved ancestor is invalid"
Oct 02 18:26:24 asia-p1 getc[4115]: INFO [10-02|18:26:24.416] Commit new mining work                   number=11323669 sealhash="11828a…89dfb7" uncles=0 txs=0  gas=0      fees=0               elapsed="237.197µs"
Oct 02 18:26:24 asia-p1 getc[4115]: INFO [10-02|18:26:24.418] Commit new mining work                   number=11323669 sealhash="bd43e8…38a8fd" uncles=0 txs=4  gas=139093 fees=0.002108368     elapsed=2.198ms
Oct 02 18:26:33 asia-p1 getc[4115]: INFO [10-02|18:26:33.041] Imported new chain segment               blocks=1  txs=11 mgas=0.286 elapsed=12.064ms    mgasps=23.713 number=11323669 hash="8602db…75765e" dirty=1.42MiB
Oct 02 18:26:33 asia-p1 getc[4115]: INFO [10-02|18:26:33.041] Commit new mining work                   number=11323670 sealhash="056c68…31c284" uncles=0 txs=0  gas=0      fees=0               elapsed="235.533µs"
Oct 02 18:26:33 asia-p1 getc[4115]: INFO [10-02|18:26:33.043] Commit new mining work                   number=11323670 sealhash="4cc13e…93432f" uncles=0 txs=3  gas=63000  fees=6.3e-05         elapsed=1.987ms
Oct 02 18:26:33 asia-p1 getc[4115]: INFO [10-02|18:26:33.219] Chain reorg detected                     number=11323668 hash="8885a2…7b56cd" drop=1 dropfrom="8602db…75765e" add=1 addfrom="e40d6d…ee96ff"

[shrikus]

Oct 02 18:25:49 us-p1 getc[23799]: INFO [10-02|18:25:49.926] Mining aborted due to sync
Oct 02 18:26:01 us-p1 getc[23799]: INFO [10-02|18:26:01.269] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=4.025ms     mgasps=0.000  number=11323668 hash="8885a2…7b56cd" dirty=1.23MiB
Oct 02 18:26:17 us-p1 getc[23799]: INFO [10-02|18:26:17.035] Deep froze chain segment                 blocks=9  elapsed=55.587ms    number=11233668 hash="805fa5…ae928b"
Oct 02 18:26:32 us-p1 getc[23799]: INFO [10-02|18:26:32.950] Imported new chain segment               blocks=1  txs=11 mgas=0.286 elapsed=6.329ms     mgasps=45.203 number=11323669 hash="8602db…75765e" dirty=1.29MiB
Oct 02 18:26:33 us-p1 getc[23799]: INFO [10-02|18:26:33.170] Imported new chain segment               blocks=1  txs=11 mgas=0.286 elapsed=6.127ms     mgasps=46.689 number=11323669 hash="e40d6d…ee96ff" dirty=1.30MiB
Oct 02 18:26:45 us-p1 getc[23799]: INFO [10-02|18:26:45.824] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=7.971ms     mgasps=0.000  number=11323670 hash="492d0d…38714f" dirty=1.31MiB
Oct 02 18:26:49 us-p1 getc[23799]: WARN [10-02|18:26:49.926] Synchronisation failed, dropping peer    peer=3fcb1f64a29c1eb0 err=timeout
Oct 02 18:26:49 us-p1 getc[23799]: INFO [10-02|18:26:49.927] Commit new mining work                   number=11323671 sealhash="9642e3…dada15" uncles=0 txs=0  gas=0      fees=0               elapsed="177.046+s"
Oct 02 18:26:49 us-p1 getc[23799]: INFO [10-02|18:26:49.928] Commit new mining work                   number=11323671 sealhash="4842aa…914aa6" uncles=0 txs=14 gas=318543 fees=0.001229403     elapsed=1.832ms
Oct 02 18:27:09 us-p1 getc[23799]: INFO [10-02|18:27:09.928] Commit new mining work                   number=11323671 sealhash="a11a16…e76cf3" uncles=0 txs=15 gas=339543 fees=0.001319703     elapsed=1.571ms
Oct 02 18:27:13 us-p1 getc[23799]: INFO [10-02|18:27:13.373] Imported new chain segment               blocks=1  txs=15 mgas=0.340 elapsed=9.700ms     mgasps=35.004 number=11323671 hash="d6f464…ed1b6f" dirty=1.37MiB
Oct 02 18:27:13 us-p1 getc[23799]: INFO [10-02|18:27:13.374] Commit new mining work                   number=11323672 sealhash="e60bd2…41223c" uncles=0 txs=0  gas=0      fees=0               elapsed="291.861+s"
Oct 02 18:27:13 us-p1 getc[23799]: INFO [10-02|18:27:13.376] Commit new mining work                   number=11323672 sealhash="e60bd2…41223c" uncles=0 txs=0  gas=0      fees=0               elapsed=2.355ms
Oct 02 18:27:17 us-p1 getc[23799]: INFO [10-02|18:27:17.083] Deep froze chain segment                 blocks=3  elapsed=48.036ms    number=11233671 hash="d7f89e…b02c36"
Oct 02 18:27:18 us-p1 getc[23799]: INFO [10-02|18:27:18.638] Mining aborted due to sync
Oct 02 18:27:18 us-p1 getc[23799]: WARN [10-02|18:27:18.643] Ancestor below allowance                 peer=b014a1ddb37fe090 number=11233671 hash="000000…000000" allowance=11233671
Oct 02 18:27:18 us-p1 getc[23799]: WARN [10-02|18:27:18.643] Synchronisation failed, dropping peer    peer=b014a1ddb37fe090 err="retrieved ancestor is invalid"
Oct 02 18:27:18 us-p1 getc[23799]: INFO [10-02|18:27:18.644] Commit new mining work                   number=11323672 sealhash="9a9dc5…d01a0a" uncles=0 txs=0  gas=0      fees=0               elapsed="170.737+s"
Oct 02 18:27:18 us-p1 getc[23799]: INFO [10-02|18:27:18.644] Commit new mining work                   number=11323672 sealhash="66f07a…a5e853" uncles=0 txs=1  gas=45543  fees=0.000956403     elapsed=1.120ms
Oct 02 18:27:28 us-p1 getc[23799]: INFO [10-02|18:27:28.623] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=4.106ms     mgasps=0.000  number=11323672 hash="24c1be…8c6658" dirty=1.38MiB
Oct 02 18:27:28 us-p1 getc[23799]: INFO [10-02|18:27:28.623] Commit new mining work                   number=11323673 sealhash="83d588…cec523" uncles=0 txs=0  gas=0      fees=0               elapsed="157.599+s"
Oct 02 18:27:28 us-p1 getc[23799]: INFO [10-02|18:27:28.624] Commit new mining work                   number=11323673 sealhash="c3178d…05a66d" uncles=0 txs=1  gas=45543  fees=0.000956403     elapsed=1.695ms
Oct 02 18:27:30 us-p1 getc[23799]: INFO [10-02|18:27:30.245] Imported new chain segment               blocks=1  txs=1  mgas=0.046 elapsed=4.879ms     mgasps=9.333  number=11323673 hash="0a1a57…73cfd2" dirty=1.39MiB
Oct 02 18:27:30 us-p1 getc[23799]: INFO [10-02|18:27:30.245] Commit new mining work                   number=11323674 sealhash="f4d3a4…309019" uncles=0 txs=0  gas=0      fees=0               elapsed="207.318+s"
Oct 02 18:27:32 us-p1 getc[23799]: INFO [10-02|18:27:32.971] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=4.408ms     mgasps=0.000  number=11323674 hash="00abc5…2f2332" dirty=1.40MiB
Oct 02 18:27:32 us-p1 getc[23799]: INFO [10-02|18:27:32.972] Commit new mining work                   number=11323675 sealhash="7241d3…6b6872" uncles=0 txs=0  gas=0      fees=0               elapsed="178.539+s"
Oct 02 18:27:38 us-p1 getc[23799]: INFO [10-02|18:27:38.063] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=4.351ms     mgasps=0.000  number=11323675 hash="5bd739…946752" dirty=1.40MiB
Oct 02 18:27:38 us-p1 getc[23799]: INFO [10-02|18:27:38.064] Commit new mining work                   number=11323676 sealhash="01f401…134a59" uncles=0 txs=0  gas=0      fees=0               elapsed="175.983+s"
Oct 02 18:27:38 us-p1 getc[23799]: INFO [10-02|18:27:38.065] Commit new mining work                   number=11323676 sealhash="4c216b…838615" uncles=0 txs=2  gas=42000  fees=0.0001806       elapsed=1.601ms
Oct 02 18:27:38 us-p1 getc[23799]: INFO [10-02|18:27:38.266] Chain reorg detected                     number=11323674 hash="00abc5…2f2332" drop=1 dropfrom="5bd739…946752" add=1 addfrom="901d18…734aca"
Oct 02 18:27:38 us-p1 getc[23799]: INFO [10-02|18:27:38.266] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=4.497ms     mgasps=0.000  number=11323675 hash="901d18…734aca" dirty=1.41MiB
Oct 02 18:27:38 us-p1 getc[23799]: INFO [10-02|18:27:38.266] Commit new mining work                   number=11323676 sealhash="286ba2…8510c0" uncles=1 txs=0  gas=0      fees=0               elapsed="195.321+s"
Oct 02 18:27:38 us-p1 getc[23799]: INFO [10-02|18:27:38.268] Commit new mining work                   number=11323676 sealhash="f8a03d…675192" uncles=1 txs=2  gas=42000  fees=0.0001806       elapsed=1.880ms
Oct 02 18:27:47 us-p1 getc[23799]: INFO [10-02|18:27:47.584] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=8.691ms     mgasps=0.000  number=11323676 hash="640151…adede5" dirty=1.41MiB
Oct 02 18:27:47 us-p1 getc[23799]: INFO [10-02|18:27:47.584] Commit new mining work                   number=11323677 sealhash="10319c…8c47d6" uncles=0 txs=0  gas=0      fees=0               elapsed="175.813+s"
Oct 02 18:27:47 us-p1 getc[23799]: INFO [10-02|18:27:47.585] Commit new mining work                   number=11323677 sealhash="295ed0…5b8b70" uncles=0 txs=2  gas=42000  fees=0.0001806       elapsed=1.326ms
Oct 02 18:28:16 us-p1 getc[23799]: INFO [10-02|18:28:16.960] Mining aborted due to sync

[BelfordZ]

thanks for the issue. Please try to keep the disrespect out of the discussion. I've taken liberty to edit your issue @slavserver to be more becoming of a gentleman such as yourself.

[meowsbits]

This appears to me to be an issue with the logging, rather an any actual problem with the miner worker.

Mining aborted due to sync is logged at Info when the recently-refactored miner is temporarily toggled for a downloader sync operation. Mining is resumed when the operation completes (Done or Failed), but no log is issued then.

As you can see, mining is aborted (tacitly because of a sync operation with a peer), the peer with found to be unhelpful (dropping peer), and the miner worker continues work (Commit new mining work).

Oct 02 18:26:24 asia-p1 getc[4115]: INFO [10-02|18:26:24.243] Mining aborted due to sync
Oct 02 18:26:24 asia-p1 getc[4115]: WARN [10-02|18:26:24.415] Ancestor below allowance                 peer=62624ff5a3abb031 number=11233668 hash="000000…000000" allowance=11233668
Oct 02 18:26:24 asia-p1 getc[4115]: WARN [10-02|18:26:24.415] Synchronisation failed, dropping peer    peer=62624ff5a3abb031 err="retrieved ancestor is invalid"
Oct 02 18:26:24 asia-p1 getc[4115]: INFO [10-02|18:26:24.416] Commit new mining work                   number=11323669 sealhash="11828a…89dfb7" uncles=0 txs=0  gas=0      fees=0               elapsed="237.197µs"
Oct 02 18:26:24 asia-p1 getc[4115]: INFO [10-02|18:26:24.418] Commit new mining work    

I would suggest adding a corresponding Miner resuming log line, and possibly bumping the log to Debug.

[meowsbits]

I changed my mind. See linked PR at ethereum/go-ethereum above for my proposed analysis and solution.