Found block height is behind

[spikeekips]

Recently I found that some node has behind Block.Height during hot body test. I ran hot body for 5 minutes and each node has block height like this,

$ for i in *.log; do echo -n $i ": "; cat $i | grep 'finish_ballot.go:54' | jq '.height' | tail -n 1; done
GAFL.DZOX.log : 29
GARD.SFM6.log : 15
GCTE.TCV6.log : 29
GCZR.RDVF.log : 29

I guess if some nodes lag behind block height, syncer will follow up to the latest, but it's not. The detailed node logs can be found at https://gist.github.com/spikeekips/701624a7c3662ca8282db7f9a0ca0363 .

[anarcher]

According to GARD.SFM6.log, The fetcher did try to fatch but failted downloading via block api. I think this is a reason that GARD.SFM6 doesn't have the same height. And fetcher tries to fetch with 172.31.22.130 and 172.31.22.219 too.

I will add more log message for api request failure.

{"caller":"fetcher.go:114","fetching_node":{"address":"GCTEOACB236P6R7ZSXOF2PSWWK7X6KRDSCQOP7WMOEZVFFZMTCV6U7O2","alias":"GCTE.TCV6","en
dpoint":"https://172.31.22.130:12001"},"height":17,"lvl":"dbug","module":"sync","msg":"fetching items from node: GCTE.TCV6","node":"GARD
.SFM6","t":"2018-11-04T13:31:02.966649829Z"}
{"caller":"fetcher.go:117","lvl":"dbug","module":"sync","msg":"apiClient","node":"GARD.SFM6","t":"2018-11-04T13:31:02.966704592Z","url":
"https://172.31.22.130:12001/node/blocks?height-range=17-18\u0026mode=full"}
{"caller":"fetcher.go:139","height":17,"items":2,"lvl":"dbug","module":"sync","msg":"fetch get items","node":"GARD.SFM6","t":"2018-11-04
T13:31:03.13806425Z"}
{"caller":"fetcher.go:87","err":"unexpected end of JSON input","lvl":"eror","module":"sync","msg":"unexpected end of JSON input","node":
"GARD.SFM6","t":"2018-11-04T13:31:03.138260788Z"}

$cat GARD.SFM6.log | grep sync | grep apiClient | grep 17-18
{"caller":"fetcher.go:117","lvl":"dbug","module":"sync","msg":"apiClient","node":"GARD.SFM6","t":"2018-11-04T13:27:55.276089281Z","url":"https://172.31.22.130:12001/node/blocks?height-range=17-18\u0026mode=full"}
{"caller":"fetcher.go:117","lvl":"dbug","module":"sync","msg":"apiClient","node":"GARD.SFM6","t":"2018-11-04T13:28:25.480215468Z","url":"https://172.31.25.219:12000/node/blocks?height-range=17-18\u0026mode=full"}
{"caller":"fetcher.go:117","lvl":"dbug","module":"sync","msg":"apiClient","node":"GARD.SFM6","t":"2018-11-04T13:28:55.590344753Z","url":"https://172.31.22.130:12001/node/blocks?height-range=17-18\u0026mode=full"}
{"caller":"fetcher.go:117","lvl":"dbug","module":"sync","msg":"apiClient","node":"GARD.SFM6","t":"2018-11-04T13:29:25.719105427Z","url":"https://172.31.22.130:12001/node/blocks?height-range=17-18\u0026mode=full"}
{"caller":"fetcher.go:117","lvl":"dbug","module":"sync","msg":"apiClient","node":"GARD.SFM6","t":"2018-11-04T13:29:55.933375211Z","url":"https://172.31.25.219:12000/node/blocks?height-range=17-18\u0026mode=full"}
{"caller":"fetcher.go:117","lvl":"dbug","module":"sync","msg":"apiClient","node":"GARD.SFM6","t":"2018-11-04T13:30:28.884899309Z","url":"https://172.31.25.219:12001/node/blocks?height-range=17-18\u0026mode=full"}
{"caller":"fetcher.go:117","lvl":"dbug","module":"sync","msg":"apiClient","node":"GARD.SFM6","t":"2018-11-04T13:31:02.966704592Z","url":"https://172.31.22.130:12001/node/blocks?height-range=17-18\u0026mode=full"}

[anarcher]

EROR[11-05|14:23:00] message:                                 module=sync node=GCDC.WBKY err="unexpected end of JSON input" height=126 statusCode=200 caller=fetcher.go:174
EROR[11-05|14:23:00] fetch err: transaction.Message unmarshal: unexpected end of JSON input module=sync node=GCDC.WBKY err="transaction.Message unmarshal: unexpected end of JSON input" height=126 caller=fetcher.go:89
EROR[11-05|14:23:00] message:                                 module=sync node=GCDC.WBKY err="unexpected end of JSON input" height=128 statusCode=200 caller=fetcher.go:174
EROR[11-05|14:23:00] fetch err: transaction.Message unmarshal: unexpected end of JSON input module=sync node=GCDC.WBKY err="transaction.Message unmarshal: unexpected end of JSON input" height=128 caller=fetcher.go:89
EROR[11-05|14:23:00] message:                                 module=sync node=GCDC.WBKY err="unexpected end of JSON input" height=132 statusCode=200 caller=fetcher.go:174

After doing sebak-hot-body, Some block heights have which tx.Message is empty.

for _, bt := range bts {
        bt, ok := bt.(block.BlockTransaction)
        if !ok {
            return errors.InvalidTransaction
        }

        var tx transaction.Transaction
        if err := json.Unmarshal(bt.Message, &tx); err != nil {
            err := pkgerrors.Wrap(err, "transaction.Message unmarshal")
            f.logger.Error(fmt.Sprintf("message: %s", bt.Message), "err", err, "height", height, "statusCode", resp.StatusCode)
            return err
        }
        txmap[bt.Hash] = &tx
    }