Node sync replay error

[ashwinrz]

SUMMARY

Running the following command during initial node sync (for validator testnet) gives an error after some time: oasis-node --config /serverdict/etc/config.yml

Specific output line that I believe is the error:
{"caller":"node.go:735","err":"tendermint: failed to create node: error during handshake: error on replay: Wrong Block.Header.AppHash. Expected F9A183178993CE3F8D10F83BB1CBD5F41650ECE387324E94BAE7116E1C54F4F3, got E3D8BA16B0321B3E1B3A706A6AAF0835803A30F7F842C2054A24324097E52A94","level":"error","module":"oasis-node","msg":"failed to start tendermint service","ts":"2020-02-28T01:20:50.060211497Z"}

ISSUE TYPE

• Bug Report

COMPONENT NAME

node.go

OASIS NODE VERSION

Software version: 20.3.2
Runtime protocol version: 0.11.0
Consensus protocol version: 0.23.0
Committee protocol version: 0.7.0
Tendermint core version: 0.32.8
ABCI library version: 0.16.1

OS / ENVIRONMENT

STEPS TO REPRODUCE

ACTUAL RESULTS

Run command->sync begins->node stopped syncing (reason unknown)->re-run command to restart sync-> error

{"caller":"prune.go:199","level":"debug","module":"abci-mux/pruner","msg":"ABCI state pruner initialized","num_kept":3600,"strategy":"none","ts":"2020-02-28T01:19:07.669063534Z"}
{"block_hash":"f9a183178993ce3f8d10f83bb1cbd5f41650ece387324e94bae7116e1c54f4f3","block_height":152154,"caller":"mux.go:884","level":"debug","module":"abci-mux","msg":"ABCI multiplexer initialized","ts":"2020-02-28T01:19:07.66912908Z"}
{"app":"100_beacon","caller":"mux.go:834","level":"debug","module":"abci-mux","msg":"Registered new application","ts":"2020-02-28T01:19:07.750467879Z"}
{"app":"999_keymanager","caller":"mux.go:834","level":"debug","module":"abci-mux","msg":"Registered new application","ts":"2020-02-28T01:19:07.750510089Z"}
{"app":"200_registry","caller":"mux.go:834","level":"debug","module":"abci-mux","msg":"Registered new application","ts":"2020-02-28T01:19:07.750539603Z"}
{"app":"100_staking","caller":"mux.go:834","level":"debug","module":"abci-mux","msg":"Registered new application","ts":"2020-02-28T01:19:07.755752257Z"}
{"app":"200_scheduler","caller":"mux.go:834","level":"debug","module":"abci-mux","msg":"Registered new application","ts":"2020-02-28T01:19:07.755807606Z"}
{"app":"999_roothash","caller":"mux.go:834","level":"debug","module":"abci-mux","msg":"Registered new application","ts":"2020-02-28T01:19:07.755841268Z"}
{"caller":"node.go:191","level":"debug","module":"oasis-node","msg":"backends initialized","ts":"2020-02-28T01:19:07.756385732Z"}
{"caller":"client.go:99","level":"warn","module":"ias/proxyclient","msg":"IAS proxy is not configured, all reports will be mocked","ts":"2020-02-28T01:19:07.757695104Z"}
{"caller":"node.go:670","level":"info","module":"oasis-node","msg":"starting Oasis node","ts":"2020-02-28T01:19:07.75816369Z"}
{"caller":"registry.go:360","level":"info","module":"runtime/registry","msg":"no supported runtimes configured","ts":"2020-02-28T01:19:07.759890566Z"}
{"caller":"worker.go:183","level":"info","module":"worker/storage","msg":"not starting storage worker as it is disabled","ts":"2020-02-28T01:19:07.771935152Z"}
{"caller":"worker.go:45","level":"info","module":"worker/executor","msg":"not starting executor worker as it is disabled","ts":"2020-02-28T01:19:07.771965064Z"}
{"caller":"worker.go:46","level":"info","module":"worker/txnscheduler","msg":"not starting transaction scheduler as it is disabled","ts":"2020-02-28T01:19:07.771987837Z"}
{"caller":"worker.go:41","level":"info","module":"worker/merge","msg":"not starting merge worker as it is disabled","ts":"2020-02-28T01:19:07.772007671Z"}
{"caller":"worker.go:58","level":"info","module":"worker/common","msg":"not starting common worker as it is disabled","ts":"2020-02-28T01:19:07.772025514Z"}
{"caller":"worker.go:87","level":"info","module":"worker/keymanager","msg":"not starting key manager worker as it is disabled","ts":"2020-02-28T01:19:07.772042673Z"}
{"caller":"worker.go:56","level":"info","module":"worker/sentry","msg":"not starting sentry worker as it is disabled","ts":"2020-02-28T01:19:07.772059843Z"}
{"caller":"worker.go:783","level":"info","module":"worker/registration","msg":"starting node registration service","ts":"2020-02-28T01:19:07.772078793Z"}
{"caller":"service.go:138","impl":"multiAppConn","level":"info","module":"tendermint:proxy","msg":"Starting multiAppConn","ts":"2020-02-28T01:20:50.057497942Z"}
{"caller":"service.go:138","connection":"query","impl":"localClient","level":"info","module":"tendermint:proxy/abci-client","msg":"Starting localClient","ts":"2020-02-28T01:20:50.057558936Z"}
{"caller":"service.go:138","connection":"mempool","impl":"localClient","level":"info","module":"tendermint:proxy/abci-client","msg":"Starting localClient","ts":"2020-02-28T01:20:50.057593345Z"}
{"caller":"service.go:138","connection":"consensus","impl":"localClient","level":"info","module":"tendermint:proxy/abci-client","msg":"Starting localClient","ts":"2020-02-28T01:20:50.057619682Z"}
{"caller":"service.go:138","impl":"EventBus","level":"info","module":"tendermint:events","msg":"Starting EventBus","ts":"2020-02-28T01:20:50.057643653Z"}
{"caller":"service.go:138","impl":"PubSub","level":"info","module":"tendermint:events/pubsub","msg":"Starting PubSub","ts":"2020-02-28T01:20:50.0576677Z"}
{"caller":"service.go:138","impl":"IndexerService","level":"info","module":"tendermint:txindex","msg":"Starting IndexerService","ts":"2020-02-28T01:20:50.057698634Z"}
{"caller":"replay.go:255","hash":"F9A183178993CE3F8D10F83BB1CBD5F41650ECE387324E94BAE7116E1C54F4F3","height":152154,"level":"info","module":"tendermint:consensus","msg":"ABCI Handshake App Info","protocol-version":1507328,"software-version":"","ts":"2020-02-28T01:20:50.057745974Z"}
{"appHeight":152154,"caller":"replay.go:293","level":"info","module":"tendermint:consensus","msg":"ABCI Replay Blocks","stateHeight":152154,"storeHeight":152155,"ts":"2020-02-28T01:20:50.057805613Z"}
{"caller":"replay.go:393","level":"info","module":"tendermint:consensus","msg":"Replay last block using real app","ts":"2020-02-28T01:20:50.057835873Z"}
{"caller":"node.go:735","err":"tendermint: failed to create node: error during handshake: error on replay: Wrong Block.Header.AppHash.  Expected F9A183178993CE3F8D10F83BB1CBD5F41650ECE387324E94BAE7116E1C54F4F3, got E3D8BA16B0321B3E1B3A706A6AAF0835803A30F7F842C2054A24324097E52A94","level":"error","module":"oasis-node","msg":"failed to start tendermint service","ts":"2020-02-28T01:20:50.060211497Z"}
{"caller":"service_manager.go:78","level":"debug","module":"oasis-node","msg":"begining cleanup","ts":"2020-02-28T01:20:50.060258021Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"tracing","ts":"2020-02-28T01:20:50.060282625Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"grpc/internal","ts":"2020-02-28T01:20:50.060303698Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"metrics","ts":"2020-02-28T01:20:50.060336802Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"pprof","ts":"2020-02-28T01:20:50.060357371Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"tendermint","ts":"2020-02-28T01:20:50.060385363Z"}
{"caller":"roothash.go:315","err":"context canceled","level":"error","module":"roothash/tendermint","msg":"failed to subscribe","ts":"2020-02-28T01:20:50.060432896Z"}
{"caller":"keymanager.go:70","err":"context canceled","level":"error","module":"keymanager/tendermint","msg":"failed to subscribe","ts":"2020-02-28T01:20:50.060377425Z"}
{"caller":"staking.go:134","err":"context canceled","level":"error","module":"staking/tendermint","msg":"failed to subscribe","ts":"2020-02-28T01:20:50.060466731Z"}
{"caller":"scheduler.go:94","err":"context canceled","level":"error","module":"scheduler/tendermint","msg":"failed to subscribe","ts":"2020-02-28T01:20:50.060516625Z"}
{"caller":"registry.go:157","err":"context canceled","level":"error","module":"registry/tendermint","msg":"failed to subscribe","ts":"2020-02-28T01:20:50.06055383Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"runtime registry","ts":"2020-02-28T01:20:50.060597959Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"client service","ts":"2020-02-28T01:20:50.060632622Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"grpc/external","ts":"2020-02-28T01:20:50.060654212Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"common worker","ts":"2020-02-28T01:20:50.060669909Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"worker node registration service","ts":"2020-02-28T01:20:50.060687908Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"key manager worker","ts":"2020-02-28T01:20:50.060701076Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"storage worker","ts":"2020-02-28T01:20:50.060715038Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"merge worker","ts":"2020-02-28T01:20:50.060732688Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"executor worker","ts":"2020-02-28T01:20:50.060751085Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"sentry worker","ts":"2020-02-28T01:20:50.06076853Z"}
{"caller":"service_manager.go:81","level":"debug","module":"oasis-node","msg":"cleaning up","svc":"transaction scheduler","ts":"2020-02-28T01:20:50.060785597Z"}
{"caller":"service_manager.go:87","level":"debug","module":"oasis-node","msg":"finished cleanup","ts":"2020-02-28T01:20:50.060804927Z"}
{"caller":"helpers.go:40","level":"info","module":"common/persistent","msg":"Got compaction priority: {level:0 score:1.73 dropPrefix:[]}","ts":"2020-02-28T01:20:50.060946799Z"}

EXPECTED RESULTS

Node sync's correctly with testnet chain

[kostko]

Duplicate of #2708, this should be fixed in 20.3.2 which has already been released, try that.

[ashwinrz]

Upgraded to the new binary (20.3.2) and the problem persists, please reopen the issue

[kostko]

Did you clear all previous state before starting the new version?

[ashwinrz]

yup - working now, thanks!