Validator not starting in devnet

[acroca]

This is a validator running in a EC2 box.

When it starts, its account had 2e+24 mtokens and 1000000000000000000 kUSD. It starts the process with the flag for the deposit set to 1e+24 tokens.

The validator syncs correctly with the devnet.

Once it syncs, the new balance is 1e+24 mtokens and 999999999999818975 kUSD

It keeps in sync with new blocks

But it seems it's not validating:

> validator.isRunning()
false
> validator.isValidating()
false

Logs: validator0.log.gz

[rgeraldes]

@acroca when adding a new validator we need to take into account that we need a certain quorum (+2/3) to mine more blocks. Given that the current network is probably with two registered validators (due to the final balance - 999999999999818975 kUSD) we will probably need to restart this network/start the same validator again since we only have one active validator(genesis) 1/2 = no quorum. If the network block number is increasing anyway that's an issue.

[acroca]

In my tests I start with 1 validator (genesis) and add 10 more at once. Maybe I can try adding them one by one better?

[JekaMas]

From 09-26|13:30:22.136 to 09-26|13:33:36.443 there're quite a lot duplicate votes for blocks like

{"log":"\u0009Block Number:\u0009\u00095145\n","stream":"stderr","time":"2018-09-26T13:30:22.136100079Z"}
{"log":"\u0009Block Hash:\u0009\u0009\u00090000000000000000000000000000000000000000000000000000000000000000\n","stream":"stderr","time":"2018-09-26T13:30:22.13610306Z"}

So it's not for a block, it's voting against the block. It really looks like each validator was voting against others, but only for 3mins ~ 180blocks.

Meantime VM returned with error09-26|13:30:15.686error is from09-26|13:30:15.686to09-26|13:31:37.049`.

The join command was {"log":"WARN [09-26|13:30:15.679] Joining the network 2 with a deposit 1000000000000000000000000. Account \"0xa4A06cb7BCaA0162082F170d4B6f4b5360DA9e11\" \n","stream":"stderr","time":"2018-09-26T13:30:15.679965068Z"}

And then sync is successful

{"log":"DEBUG[09-26|13:46:07.444] Queued propagated block                  peer=cdced4c605a2383c number=6076 hash=9a45a7…a89741 queued=1\n","stream":"stderr","time":"2018-09-26T13:46:07.445121387Z"}
{"log":"DEBUG[09-26|13:46:07.445] Importing propagated block               peer=cdced4c605a2383c number=6076 hash=9a45a7…a89741\n","stream":"stderr","time":"2018-09-26T13:46:07.44565494Z"}
{"log":"DEBUG[09-26|13:46:07.445] Synchronising with the network           peer=cdced4c605a2383c kcoin=1 head=9a45a7…a89741 block number=6076 mode=full\n","stream":"stderr","time":"2018-09-26T13:46:07.445760387Z"}
{"log":"DEBUG[09-26|13:46:07.445] Retrieving remote chain height           peer=cdced4c605a2383c\n","stream":"stderr","time":"2018-09-26T13:46:07.445765281Z"}
{"log":"DEBUG[09-26|13:46:07.445] Fetching batch of headers                id=cdced4c605a2383c conn=inbound    count=1   fromhash=9a45a7…a89741 skip=0   reverse=false\n","stream":"stderr","time":"2018-09-26T13:46:07.445832206Z"}
{"log":"DEBUG[09-26|13:46:07.446] Trie cache stats after commit            misses=0 unloads=0\n","stream":"stderr","time":"2018-09-26T13:46:07.446592646Z"}
{"log":"DEBUG[09-26|13:46:07.446] Dereferenced trie from memory database   nodes=4 size=1.20kB time=13.445µs   gcnodes=2412 gcsize=723.00kB gctime=18.001267ms livenodes=513 livesize=153.47kB\n","stream":"stderr","time":"2018-09-26T13:46:07.446651052Z"}
{"log":"DEBUG[09-26|13:46:07.446] Inserted new block                       number=6076 hash=9a45a7…a89741 txs=0  gas=0 elapsed=710.305µs\n","stream":"stderr","time":"2018-09-26T13:46:07.446770444Z"}
{"log":"INFO [09-26|13:46:07.446] Imported new chain segment               blocks=1  txs=0  mgas=0.000 elapsed=741.03µs       mgasps=0.000 number=6076 hash=9a45a7…a89741 cache=186.24kB\n","stream":"stderr","time":"2018-09-26T13:46:07.446776343Z"}
{"log":"TRACE[09-26|13:46:07.446] Propagated block                         hash=9a45a7…a89741 recipients=2  duration=2.220ms\n","stream":"stderr","time":"2018-09-26T13:46:07.446872079Z"}
{"log":"TRACE[09-26|13:46:07.446] Propagated block                         id=e7dfdcca5efc2c7d conn=inbound    number=6076 hash=9a45a7…a89741\n","stream":"stderr","time":"2018-09-26T13:46:07.447007637Z"}
{"log":"TRACE[09-26|13:46:07.447] Announced block                          hash=9a45a7…a89741 recipients=4  duration=2.545ms\n","stream":"stderr","time":"2018-09-26T13:46:07.450064086Z"}
{"log":"TRACE[09-26|13:46:07.447] Announced block                          id=821e222617374937 conn=staticdial number=6076 hash=9a45a7…a89741\n","stream":"stderr","time":"2018-09-26T13:46:07.450074877Z"}
{"log":"DEBUG[09-26|13:46:07.447] Reinjecting stale transactions           count=0\n","stream":"stderr","time":"2018-09-26T13:46:07.450078419Z"}
{"log":"TRACE[09-26|13:46:07.447] Announced block                          id=1d3e2a308aa32e34 conn=inbound    number=6076 hash=9a45a7…a89741\n","stream":"stderr","time":"2018-09-26T13:46:07.450081622Z"}
{"log":"DEBUG[09-26|13:46:07.447] Queued propagated block                  peer=536b08de0cbf8be0 number=6076 hash=9a45a7…a89741 queued=1\n","stream":"stderr","time":"2018-09-26T13:46:07.450084914Z"}
{"log":"TRACE[09-26|13:46:07.447] Filtering headers                        peer=cdced4c605a2383c headers=1\n","stream":"stderr","time":"2018-09-26T13:46:07.450174216Z"}
{"log":"DEBUG[09-26|13:46:07.450] Remote head header identified            number=6076 hash=9a45a7…a89741\n","stream":"stderr","time":"2018-09-26T13:46:07.450181429Z"}
{"log":"DEBUG[09-26|13:46:07.450] Looking for common ancestor              peer=cdced4c605a2383c local=6076 remote=6076\n","stream":"stderr","time":"2018-09-26T13:46:07.450185064Z"}
{"log":"DEBUG[09-26|13:46:07.450] Fetching batch of headers                id=cdced4c605a2383c conn=inbound    count=13  fromnum=5884 skip=15  reverse=false\n","stream":"stderr","time":"2018-09-26T13:46:07.450227836Z"}
{"log":"TRACE[09-26|13:46:07.448] Announced block                          id=19b5e9c0b5c98184 conn=inbound    number=6076 hash=9a45a7…a89741\n","stream":"stderr","time":"2018-09-26T13:46:07.450308146Z"}
{"log":"TRACE[09-26|13:46:07.448] Announced block                          id=b619a7662c5874c4 conn=inbound    number=6076 hash=9a45a7…a89741\n","stream":"stderr","time":"2018-09-26T13:46:07.450315678Z"}
{"log":"TRACE[09-26|13:46:07.448] Propagated block                         id=536b08de0cbf8be0 conn=staticdial number=6076 hash=9a45a7…a89741\n","stream":"stderr","time":"2018-09-26T13:46:07.450319245Z"}
{"log":"TRACE[09-26|13:46:09.941] Propagated block                         hash=a2ba47…3d19d6 recipients=3  duration=3.240ms\n","stream":"stderr","time":"2018-09-26T13:46:09.94168128Z"}
{"log":"TRACE[09-26|13:46:09.941] Propagated block                         id=821e222617374937 conn=staticdial number=6078 hash=a2ba47

In total I think:

1. we need more detailed errors from solidity side, err=\"evm: execution reverted\"\n" don't help much to debug things - https://github.com/kowala-tech/kcoin/pull/802
2. more detailed errors for duplicate vote - https://github.com/kowala-tech/kcoin/pull/797
3. if we want >1 validator, we need to complete https://github.com/kowala-tech/kcoin/issues/787

@acroca @rgeraldes @yourheropaul

[yourheropaul]

#797 is merged now. I'll look into solidity debugging

[yourheropaul]

There's now an issue for the solidity error tracer: #802.