Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

clique perpetual resync from ~block3000 #75

Closed
meowsbits opened this issue Mar 18, 2020 · 1 comment · Fixed by #78
Closed

clique perpetual resync from ~block3000 #75

meowsbits opened this issue Mar 18, 2020 · 1 comment · Fixed by #78
Labels
F2-bug 🐞 P2-asap 🌊

Comments

@meowsbits
Copy link
Member

meowsbits commented Mar 18, 2020 •
edited
Loading

Visible on Kotti.

For some geth clients on Kotti (a clique consensus network), they can be seen to sync with the network and then eventually "rewind"/"fall back"/whatever to about block 3000, and then do a whole lot of heavy sidechain imports.

More information and investigation to follow.

  • An example log file which has been filtered to try to show most relevant lines: https://gist.github.com/4fc03ad11e22ce8c1de032b4add94b96

    • (the "filter" i mean is just cat core-geth.kotti.fullsync.service.logs | grep -v -E '(admin_peers|stats|peer|Suppressed|Deref|handshake|Served|Writing prev|Inserted known|QoS|Bad packet|Revalidated node|Removed dead node|Bad discv4)' > core-geth.kotti.resync.log.filtered)
@meowsbits
Copy link
Member Author

meowsbits commented Mar 18, 2020 •
edited
Loading

I ran the following to stress test geth with some repeated uncatchable kills

> for i in {1..100}; do kill -9 $(ps x | grep kotti | grep -v journal |grep -v bin/sh |grep -v grep | grep kotti.full | cut -d' ' -f1) || exit 1; sleep 60; done

Caught the following.
Full log at: https://gist.github.com/e41ad87b162587aa830dee8b41185651

: DEBUG[03-18|08:31:36.313] Removing p2p peer                        peercount=3  id=30d98c848dd368ac duration=6.574ms    req=false err=EOF
: DEBUG[03-18|08:31:36.327] Adding p2p peer                          peercount=4  id=30d70f9105ba2483 conn=dyndial         addr=207.148.25.252:30305  name=Geth/v1.3.0-Ether1-K...
: DEBUG[03-18|08:31:36.327] Ethereum peer connected                  id=30d70f9105ba2483 conn=dyndial         name=Geth/v1.3.0-Ether1-Kronos/linux-amd64/go1.13.4
: DEBUG[03-18|08:31:36.385] Adding p2p peer                          peercount=5  id=301d5b85893602d1 conn=dyndial         addr=31.200.231.26:30309   name=Geth/aka.farmine.ru/...
: DEBUG[03-18|08:31:36.385] Ethereum peer connected                  id=301d5b85893602d1 conn=dyndial         name=Geth/aka.farmine.ru/v0.4.2-akroma-b00f8ca4/linux-amd64/go1.11.1
: DEBUG[03-18|08:31:36.424] Ethereum handshake failed                id=3078aaf623220c60 conn=dyndial         err=EOF
: DEBUG[03-18|08:31:36.424] Removing p2p peer                        peercount=4  id=3078aaf623220c60 duration=250.449ms  req=true  err="subprotocol error"
: DEBUG[03-18|08:31:36.436] Adding p2p peer                          peercount=5  id=301b8d75aa93dd43 conn=dyndial         addr=198.177.241.35:30303  name=Geth/v1.8.23-stable/...
: DEBUG[03-18|08:31:36.437] Ethereum peer connected                  id=301b8d75aa93dd43 conn=dyndial         name=Geth/v1.8.23-stable/linux-amd64/go1.11.13
: DEBUG[03-18|08:31:36.464] Adding p2p peer                          peercount=6  id=a6d9976058be4689 conn=dyndial         addr=52.79.47.93:30303     name=Parity-Ethereum/v2.5...
: DEBUG[03-18|08:31:36.464] Ethereum peer connected                  id=a6d9976058be4689 conn=dyndial         name=Parity-Ethereum/v2.5.13-unstable-253ff3f-20191231/x86_64-linux-gnu/rustc1.40.0
: DEBUG[03-18|08:31:36.470] Ethereum handshake failed                id=a6d9976058be4689 conn=dyndial         err=EOF
: DEBUG[03-18|08:31:36.470] Removing p2p peer                        peercount=5  id=a6d9976058be4689 duration=5.704ms    req=false err=EOF
: DEBUG[03-18|08:31:36.615] Ethereum handshake failed                id=30d70f9105ba2483 conn=dyndial         err=EOF
: DEBUG[03-18|08:31:36.615] Removing p2p peer                        peercount=4  id=30d70f9105ba2483 duration=287.982ms  req=true  err="subprotocol error"
: DEBUG[03-18|08:31:36.733] Ethereum handshake failed                id=301d5b85893602d1 conn=dyndial         err="Genesis mismatch - 679ee3d5213ddab6 (!= 14c2283285a88fe5)"
: DEBUG[03-18|08:31:36.733] Removing p2p peer                        peercount=3  id=301d5b85893602d1 duration=348.566ms  req=true  err="subprotocol error"
: DEBUG[03-18|08:31:36.771] Ethereum handshake failed                id=301b8d75aa93dd43 conn=dyndial         err="Genesis mismatch - d4e56740f876aef8 (!= 14c2283285a88fe5)"
: DEBUG[03-18|08:31:36.771] Removing p2p peer                        peercount=2  id=301b8d75aa93dd43 duration=335.002ms  req=false err="Genesis mismatch - d4e56740f876aef8 (!= 14c2283285a88fe5)"
: Killed
: multigeth.kotti.full.service: Main process exited, code=exited, status=137/n/a
: multigeth.kotti.full.service: Failed with result 'exit-code'.
: multigeth.kotti.full.service: Service hold-off time over, scheduling restart.
: multigeth.kotti.full.service: Scheduled restart job, restart counter is at 1.
: Stopped EChain kotti Service.
: Started EChain kotti Service.
: INFO [03-18|08:31:39.978] Bumping default cache on mainnet         provided=1024 updated=4096
: DEBUG[03-18|08:31:39.978] Sanitizing Go's GC trigger               percent=25
: INFO [03-18|08:31:39.979] Maximum peer count                       ETH=50 LES=100 total=150
: INFO [03-18|08:31:39.979] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
: DEBUG[03-18|08:31:39.980] FS scan times                            list=62.41µs set=811ns diff=819ns
: INFO [03-18|08:31:39.982] Starting peer-to-peer node               instance=CoreGeth/v1.11.2-unstable-1195f0da-20200318/linux-amd64/go1.13.5
: INFO [03-18|08:31:39.982] Allocated trie memory caches             clean=1024.00MiB dirty=1024.00MiB
: INFO [03-18|08:31:39.982] Allocated cache and file handles         database=/home/ia/SAMSUNG_T5/e/clients/multigeth/kotti.full/geth/chaindata cache=2.00GiB handles=2048
: DEBUG[03-18|08:31:46.252] Chain freezer table opened               database=/home/ia/SAMSUNG_T5/e/clients/multigeth/kotti.full/geth/chaindata/ancient table=headers items=1971437 size=561.45MiB
: DEBUG[03-18|08:31:46.255] Chain freezer table opened               database=/home/ia/SAMSUNG_T5/e/clients/multigeth/kotti.full/geth/chaindata/ancient table=hashes  items=1971437 size=60.16MiB
: DEBUG[03-18|08:31:46.261] Chain freezer table opened               database=/home/ia/SAMSUNG_T5/e/clients/multigeth/kotti.full/geth/chaindata/ancient table=bodies  items=1971437 size=14.42MiB
: DEBUG[03-18|08:31:46.264] Chain freezer table opened               database=/home/ia/SAMSUNG_T5/e/clients/multigeth/kotti.full/geth/chaindata/ancient table=receipts items=1971437 size=6.01MiB
: DEBUG[03-18|08:31:46.269] Chain freezer table opened               database=/home/ia/SAMSUNG_T5/e/clients/multigeth/kotti.full/geth/chaindata/ancient table=diffs    items=1971437 size=7.49MiB
: INFO [03-18|08:31:46.269] Opened ancient database                  database=/home/ia/SAMSUNG_T5/e/clients/multigeth/kotti.full/geth/chaindata/ancient
: DEBUG[03-18|08:31:46.281] Ancient blocks frozen already            number=2061437 hash=007e16…16f690 frozen=1971437
: INFO [03-18|08:31:46.285] Persisted trie from memory database      nodes=357 size=50.66KiB  time=942.849µs gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=0.00B
: INFO [03-18|08:31:46.285] Found stored genesis block               config="NetworkID: 6, ChainID: 6 Engine: clique EIP1014: 1705549 EIP1052: 1705549 EIP1108: 2200013 EIP1344: 2200013 EIP140: 716617 EIP145: 1705549 EIP150: 0 EIP152: 2200013 EIP155: 0 EIP160: 0 EIP161abc: 716617 EIP161d: 716617 EIP170: 716617 EIP1884: 2200013 EIP198: 716617 EIP2028: 2200013 EIP211: 716617 EIP212: 716617 EIP213: 716617 EIP214: 716617 EIP2200: 2200013 EIP658: 716617 EIP7: 0 EthashECIP1010Continue: 2000000 EthashECIP1010Pause: 0 EthashECIP1017: 5000000 EthashECIP1041: 0 EthashEIP100B: 716617 EthashEIP2: 0 EthashHomestead: 0 "
: INFO [03-18|08:31:46.286] Initialised chain configuration          config="NetworkID: 6, ChainID: 6 Engine: clique EIP1014: 1705549 EIP1052: 1705549 EIP1108: 2200013 EIP1344: 2200013 EIP140: 716617 EIP145: 1705549 EIP150: 0 EIP152: 2200013 EIP155: 0 EIP160: 0 EIP161abc: 716617 EIP161d: 716617 EIP170: 716617 EIP1884: 2200013 EIP198: 716617 EIP2028: 2200013 EIP211: 716617 EIP212: 716617 EIP213: 716617 EIP214: 716617 EIP2200: 2200013 EIP658: 716617 EIP7: 0 EthashECIP1010Continue: 2000000 EthashECIP1010Pause: 0 EthashECIP1017: 5000000 EthashECIP1041: 0 EthashEIP100B: 716617 EthashEIP2: 0 EthashHomestead: 0 "
: INFO [03-18|08:31:46.287] Initialising Ethereum protocol           versions="[65 64 63]" network=6 dbversion=7
: WARN [03-18|08:31:46.288] Head state missing, repairing chain      number=2061437 hash=007e16…16f690
: INFO [03-18|08:32:45.365] Rewound blockchain to past state         number=3734    hash=40292e…1172fa
: INFO [03-18|08:32:45.365] Loaded most recent local header          number=2061437 hash=007e16…16f690 td=3264910 age=1m18s
: INFO [03-18|08:32:45.365] Loaded most recent local full block      number=3734    hash=40292e…1172fa td=7469    age=1y1mo4w
: INFO [03-18|08:32:45.365] Loaded most recent local fast block      number=2061437 hash=007e16…16f690 td=3264910 age=1m18s
: DEBUG[03-18|08:32:46.282] Current full block not old enough        number=3734    hash=40292e…1172fa delay=90000

This was referenced Mar 18, 2020
Closed
Merged
@q9f q9f mentioned this issue Mar 30, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
F2-bug 🐞 P2-asap 🌊
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix/loop-sync-mode etclabscore/core-geth
1 participant
@meowsbits