neo-go/pkg/consensus/consensus_test.go

283 lines
7.3 KiB
Go
Raw Normal View History

package consensus
import (
"testing"
consensus: prevent synchronization stalls When CN is not up to date with the network is synchonizes blocks first and only then starts consensus process. But while synchronizing it receives consensus payloads and tries to process them even though messages reader routine is not started yet. This leads to lots of goroutines waiting to send their messages: Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639919 [chan send, 4 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc005bd7680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc00507d170, 0xc005bdd560, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc00507d170) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639181 [chan send, 10 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc013bb6600) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc01361ee10, 0xc01342c780, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc01361ee10) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 39454 [chan send, 32 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc014fea680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc0140b2ea0, 0xc014fe0ed0, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc0140b2ea0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Luckily it doesn't break synchronization completely as eventually connection timers fire, the node breaks all connections, create new ones and these new ones request blocks successfully until another consensus payload stalls them too. In the end the node reaches synchronization, message processing loop starts and releases all of these waiting goroutines, but it's better for us to avoid this happening at all. This also makes double-starting a no-op which is a nice property.
2020-06-26 08:19:01 +00:00
"time"
"github.com/nspcc-dev/dbft/block"
"github.com/nspcc-dev/dbft/payload"
"github.com/nspcc-dev/neo-go/pkg/config"
"github.com/nspcc-dev/neo-go/pkg/config/netmode"
"github.com/nspcc-dev/neo-go/pkg/core"
"github.com/nspcc-dev/neo-go/pkg/core/storage"
"github.com/nspcc-dev/neo-go/pkg/core/transaction"
"github.com/nspcc-dev/neo-go/pkg/crypto/keys"
"github.com/nspcc-dev/neo-go/pkg/internal/testchain"
2020-04-21 13:45:48 +00:00
"github.com/nspcc-dev/neo-go/pkg/io"
"github.com/nspcc-dev/neo-go/pkg/smartcontract"
"github.com/nspcc-dev/neo-go/pkg/util"
2020-04-21 13:45:48 +00:00
"github.com/nspcc-dev/neo-go/pkg/vm/emit"
"github.com/nspcc-dev/neo-go/pkg/vm/opcode"
"github.com/stretchr/testify/require"
2019-12-30 07:43:05 +00:00
"go.uber.org/zap/zaptest"
)
func TestNewService(t *testing.T) {
srv := newTestService(t)
tx := transaction.New(netmode.UnitTestNet, []byte{byte(opcode.PUSH1)}, 100000)
tx.ValidUntilBlock = 1
addSender(t, tx)
signTx(t, srv.Chain.FeePerByte(), tx)
require.NoError(t, srv.Chain.PoolTx(tx))
var txx []block.Transaction
require.NotPanics(t, func() { txx = srv.getVerifiedTx() })
require.Len(t, txx, 1)
require.Equal(t, tx, txx[0])
consensus: close chain in tests Avoid test failures like this one: === RUN TestService_OnPayload ================== WARNING: DATA RACE Read at 0x00c00015a843 by goroutine 112: testing.(*common).logDepth() /usr/local/go/src/testing/testing.go:665 +0xa1 testing.(*common).Logf() /usr/local/go/src/testing/testing.go:658 +0x8f testing.(*T).Logf() <autogenerated>:1 +0x75 go.uber.org/zap/zaptest.testingWriter.Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zaptest/logger.go:130 +0x11f go.uber.org/zap/zaptest.(*testingWriter).Write() <autogenerated>:1 +0xa9 go.uber.org/zap/zapcore.(*ioCore).Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zapcore/core.go:90 +0x1c3 go.uber.org/zap/zapcore.(*CheckedEntry).Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zapcore/entry.go:215 +0x1e7 go.uber.org/zap.(*Logger).Info() /go/pkg/mod/go.uber.org/zap@v1.10.0/logger.go:187 +0x95 github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).persist() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:720 +0x6bb github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).Run.func2() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:228 +0x53 Previous write at 0x00c00015a843 by goroutine 98: testing.tRunner.func1() /usr/local/go/src/testing/testing.go:900 +0x353 testing.tRunner() /usr/local/go/src/testing/testing.go:913 +0x1bb Goroutine 112 (running) created at: github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).Run() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:227 +0x264 Goroutine 98 (finished) created at: testing.(*T).Run() /usr/local/go/src/testing/testing.go:960 +0x651 testing.runTests.func1() /usr/local/go/src/testing/testing.go:1202 +0xa6 testing.tRunner() /usr/local/go/src/testing/testing.go:909 +0x199 testing.runTests() /usr/local/go/src/testing/testing.go:1200 +0x521 testing.(*M).Run() /usr/local/go/src/testing/testing.go:1117 +0x2ff main.main() _testmain.go:162 +0x337 ================== --- FAIL: TestService_OnPayload (4.11s)
2020-01-20 16:40:52 +00:00
srv.Chain.Close()
}
func TestService_GetVerified(t *testing.T) {
srv := newTestService(t)
consensus: prevent synchronization stalls When CN is not up to date with the network is synchonizes blocks first and only then starts consensus process. But while synchronizing it receives consensus payloads and tries to process them even though messages reader routine is not started yet. This leads to lots of goroutines waiting to send their messages: Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639919 [chan send, 4 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc005bd7680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc00507d170, 0xc005bdd560, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc00507d170) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639181 [chan send, 10 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc013bb6600) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc01361ee10, 0xc01342c780, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc01361ee10) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 39454 [chan send, 32 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc014fea680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc0140b2ea0, 0xc014fe0ed0, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc0140b2ea0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Luckily it doesn't break synchronization completely as eventually connection timers fire, the node breaks all connections, create new ones and these new ones request blocks successfully until another consensus payload stalls them too. In the end the node reaches synchronization, message processing loop starts and releases all of these waiting goroutines, but it's better for us to avoid this happening at all. This also makes double-starting a no-op which is a nice property.
2020-06-26 08:19:01 +00:00
srv.dbft.Start()
var txs []*transaction.Transaction
for i := 0; i < 4; i++ {
tx := transaction.New(netmode.UnitTestNet, []byte{byte(opcode.PUSH1)}, 100000)
tx.Nonce = 123 + uint32(i)
tx.ValidUntilBlock = 1
txs = append(txs, tx)
}
addSender(t, txs...)
signTx(t, srv.Chain.FeePerByte(), txs...)
require.NoError(t, srv.Chain.PoolTx(txs[3]))
hashes := []util.Uint256{txs[0].Hash(), txs[1].Hash(), txs[2].Hash()}
consensus: prevent synchronization stalls When CN is not up to date with the network is synchonizes blocks first and only then starts consensus process. But while synchronizing it receives consensus payloads and tries to process them even though messages reader routine is not started yet. This leads to lots of goroutines waiting to send their messages: Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639919 [chan send, 4 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc005bd7680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc00507d170, 0xc005bdd560, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc00507d170) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639181 [chan send, 10 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc013bb6600) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc01361ee10, 0xc01342c780, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc01361ee10) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 39454 [chan send, 32 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc014fea680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc0140b2ea0, 0xc014fe0ed0, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc0140b2ea0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Luckily it doesn't break synchronization completely as eventually connection timers fire, the node breaks all connections, create new ones and these new ones request blocks successfully until another consensus payload stalls them too. In the end the node reaches synchronization, message processing loop starts and releases all of these waiting goroutines, but it's better for us to avoid this happening at all. This also makes double-starting a no-op which is a nice property.
2020-06-26 08:19:01 +00:00
// Everyone sends a message.
for i := 0; i < 4; i++ {
p := new(Payload)
p.message = &message{}
// One PrepareRequest and three ChangeViews.
if i == 1 {
p.SetType(payload.PrepareRequestType)
p.SetPayload(&prepareRequest{transactionHashes: hashes})
} else {
p.SetType(payload.ChangeViewType)
p.SetPayload(&changeView{newViewNumber: 1, timestamp: uint64(time.Now().UnixNano() / nsInMs)})
consensus: prevent synchronization stalls When CN is not up to date with the network is synchonizes blocks first and only then starts consensus process. But while synchronizing it receives consensus payloads and tries to process them even though messages reader routine is not started yet. This leads to lots of goroutines waiting to send their messages: Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639919 [chan send, 4 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc005bd7680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc00507d170, 0xc005bdd560, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc00507d170) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639181 [chan send, 10 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc013bb6600) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc01361ee10, 0xc01342c780, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc01361ee10) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 39454 [chan send, 32 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc014fea680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc0140b2ea0, 0xc014fe0ed0, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc0140b2ea0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Luckily it doesn't break synchronization completely as eventually connection timers fire, the node breaks all connections, create new ones and these new ones request blocks successfully until another consensus payload stalls them too. In the end the node reaches synchronization, message processing loop starts and releases all of these waiting goroutines, but it's better for us to avoid this happening at all. This also makes double-starting a no-op which is a nice property.
2020-06-26 08:19:01 +00:00
}
p.SetHeight(1)
p.SetValidatorIndex(uint16(i))
consensus: prevent synchronization stalls When CN is not up to date with the network is synchonizes blocks first and only then starts consensus process. But while synchronizing it receives consensus payloads and tries to process them even though messages reader routine is not started yet. This leads to lots of goroutines waiting to send their messages: Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639919 [chan send, 4 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc005bd7680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc00507d170, 0xc005bdd560, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc00507d170) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639181 [chan send, 10 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc013bb6600) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc01361ee10, 0xc01342c780, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc01361ee10) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 39454 [chan send, 32 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc014fea680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc0140b2ea0, 0xc014fe0ed0, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc0140b2ea0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Luckily it doesn't break synchronization completely as eventually connection timers fire, the node breaks all connections, create new ones and these new ones request blocks successfully until another consensus payload stalls them too. In the end the node reaches synchronization, message processing loop starts and releases all of these waiting goroutines, but it's better for us to avoid this happening at all. This also makes double-starting a no-op which is a nice property.
2020-06-26 08:19:01 +00:00
priv, _ := getTestValidator(i)
require.NoError(t, p.Sign(priv))
consensus: prevent synchronization stalls When CN is not up to date with the network is synchonizes blocks first and only then starts consensus process. But while synchronizing it receives consensus payloads and tries to process them even though messages reader routine is not started yet. This leads to lots of goroutines waiting to send their messages: Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639919 [chan send, 4 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc005bd7680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc00507d170, 0xc005bdd560, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc00507d170) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639181 [chan send, 10 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc013bb6600) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc01361ee10, 0xc01342c780, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc01361ee10) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 39454 [chan send, 32 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc014fea680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc0140b2ea0, 0xc014fe0ed0, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc0140b2ea0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Luckily it doesn't break synchronization completely as eventually connection timers fire, the node breaks all connections, create new ones and these new ones request blocks successfully until another consensus payload stalls them too. In the end the node reaches synchronization, message processing loop starts and releases all of these waiting goroutines, but it's better for us to avoid this happening at all. This also makes double-starting a no-op which is a nice property.
2020-06-26 08:19:01 +00:00
// Skip srv.OnPayload, because the service is not really started.
srv.dbft.OnReceive(p)
}
require.Equal(t, uint8(1), srv.dbft.ViewNumber)
require.Equal(t, hashes, srv.lastProposal)
t.Run("new transactions will be proposed in case of failure", func(t *testing.T) {
txx := srv.getVerifiedTx()
require.Equal(t, 1, len(txx), "there is only 1 tx in mempool")
require.Equal(t, txs[3], txx[0])
})
t.Run("more than half of the last proposal will be reused", func(t *testing.T) {
for _, tx := range txs[:2] {
require.NoError(t, srv.Chain.PoolTx(tx))
}
txx := srv.getVerifiedTx()
require.Contains(t, txx, txs[0])
require.Contains(t, txx, txs[1])
require.NotContains(t, txx, txs[2])
})
consensus: close chain in tests Avoid test failures like this one: === RUN TestService_OnPayload ================== WARNING: DATA RACE Read at 0x00c00015a843 by goroutine 112: testing.(*common).logDepth() /usr/local/go/src/testing/testing.go:665 +0xa1 testing.(*common).Logf() /usr/local/go/src/testing/testing.go:658 +0x8f testing.(*T).Logf() <autogenerated>:1 +0x75 go.uber.org/zap/zaptest.testingWriter.Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zaptest/logger.go:130 +0x11f go.uber.org/zap/zaptest.(*testingWriter).Write() <autogenerated>:1 +0xa9 go.uber.org/zap/zapcore.(*ioCore).Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zapcore/core.go:90 +0x1c3 go.uber.org/zap/zapcore.(*CheckedEntry).Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zapcore/entry.go:215 +0x1e7 go.uber.org/zap.(*Logger).Info() /go/pkg/mod/go.uber.org/zap@v1.10.0/logger.go:187 +0x95 github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).persist() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:720 +0x6bb github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).Run.func2() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:228 +0x53 Previous write at 0x00c00015a843 by goroutine 98: testing.tRunner.func1() /usr/local/go/src/testing/testing.go:900 +0x353 testing.tRunner() /usr/local/go/src/testing/testing.go:913 +0x1bb Goroutine 112 (running) created at: github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).Run() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:227 +0x264 Goroutine 98 (finished) created at: testing.(*T).Run() /usr/local/go/src/testing/testing.go:960 +0x651 testing.runTests.func1() /usr/local/go/src/testing/testing.go:1202 +0xa6 testing.tRunner() /usr/local/go/src/testing/testing.go:909 +0x199 testing.runTests() /usr/local/go/src/testing/testing.go:1200 +0x521 testing.(*M).Run() /usr/local/go/src/testing/testing.go:1117 +0x2ff main.main() _testmain.go:162 +0x337 ================== --- FAIL: TestService_OnPayload (4.11s)
2020-01-20 16:40:52 +00:00
srv.Chain.Close()
}
2019-12-16 08:57:49 +00:00
func TestService_ValidatePayload(t *testing.T) {
srv := newTestService(t)
priv, _ := getTestValidator(1)
p := new(Payload)
p.message = &message{}
2019-12-16 08:57:49 +00:00
p.SetPayload(&prepareRequest{})
t.Run("invalid validator index", func(t *testing.T) {
p.SetValidatorIndex(11)
require.NoError(t, p.Sign(priv))
var ok bool
require.NotPanics(t, func() { ok = srv.validatePayload(p) })
require.False(t, ok)
})
t.Run("wrong validator index", func(t *testing.T) {
p.SetValidatorIndex(2)
require.NoError(t, p.Sign(priv))
require.False(t, srv.validatePayload(p))
})
t.Run("normal case", func(t *testing.T) {
p.SetValidatorIndex(1)
require.NoError(t, p.Sign(priv))
require.True(t, srv.validatePayload(p))
})
consensus: close chain in tests Avoid test failures like this one: === RUN TestService_OnPayload ================== WARNING: DATA RACE Read at 0x00c00015a843 by goroutine 112: testing.(*common).logDepth() /usr/local/go/src/testing/testing.go:665 +0xa1 testing.(*common).Logf() /usr/local/go/src/testing/testing.go:658 +0x8f testing.(*T).Logf() <autogenerated>:1 +0x75 go.uber.org/zap/zaptest.testingWriter.Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zaptest/logger.go:130 +0x11f go.uber.org/zap/zaptest.(*testingWriter).Write() <autogenerated>:1 +0xa9 go.uber.org/zap/zapcore.(*ioCore).Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zapcore/core.go:90 +0x1c3 go.uber.org/zap/zapcore.(*CheckedEntry).Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zapcore/entry.go:215 +0x1e7 go.uber.org/zap.(*Logger).Info() /go/pkg/mod/go.uber.org/zap@v1.10.0/logger.go:187 +0x95 github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).persist() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:720 +0x6bb github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).Run.func2() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:228 +0x53 Previous write at 0x00c00015a843 by goroutine 98: testing.tRunner.func1() /usr/local/go/src/testing/testing.go:900 +0x353 testing.tRunner() /usr/local/go/src/testing/testing.go:913 +0x1bb Goroutine 112 (running) created at: github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).Run() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:227 +0x264 Goroutine 98 (finished) created at: testing.(*T).Run() /usr/local/go/src/testing/testing.go:960 +0x651 testing.runTests.func1() /usr/local/go/src/testing/testing.go:1202 +0xa6 testing.tRunner() /usr/local/go/src/testing/testing.go:909 +0x199 testing.runTests() /usr/local/go/src/testing/testing.go:1200 +0x521 testing.(*M).Run() /usr/local/go/src/testing/testing.go:1117 +0x2ff main.main() _testmain.go:162 +0x337 ================== --- FAIL: TestService_OnPayload (4.11s)
2020-01-20 16:40:52 +00:00
srv.Chain.Close()
2019-12-16 08:57:49 +00:00
}
2019-12-27 11:09:58 +00:00
func TestService_getTx(t *testing.T) {
srv := newTestService(t)
t.Run("transaction in mempool", func(t *testing.T) {
tx := transaction.New(netmode.UnitTestNet, []byte{byte(opcode.PUSH1)}, 0)
tx.Nonce = 1234
tx.ValidUntilBlock = 1
addSender(t, tx)
signTx(t, srv.Chain.FeePerByte(), tx)
2019-12-27 11:09:58 +00:00
h := tx.Hash()
require.Equal(t, nil, srv.getTx(h))
require.NoError(t, srv.Chain.PoolTx(tx))
2019-12-27 11:09:58 +00:00
got := srv.getTx(h)
require.NotNil(t, got)
require.Equal(t, h, got.Hash())
})
t.Run("transaction in local cache", func(t *testing.T) {
tx := transaction.New(netmode.UnitTestNet, []byte{byte(opcode.PUSH1)}, 0)
tx.Nonce = 4321
tx.ValidUntilBlock = 1
2019-12-27 11:09:58 +00:00
h := tx.Hash()
require.Equal(t, nil, srv.getTx(h))
srv.txx.Add(tx)
got := srv.getTx(h)
require.NotNil(t, got)
require.Equal(t, h, got.Hash())
})
consensus: close chain in tests Avoid test failures like this one: === RUN TestService_OnPayload ================== WARNING: DATA RACE Read at 0x00c00015a843 by goroutine 112: testing.(*common).logDepth() /usr/local/go/src/testing/testing.go:665 +0xa1 testing.(*common).Logf() /usr/local/go/src/testing/testing.go:658 +0x8f testing.(*T).Logf() <autogenerated>:1 +0x75 go.uber.org/zap/zaptest.testingWriter.Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zaptest/logger.go:130 +0x11f go.uber.org/zap/zaptest.(*testingWriter).Write() <autogenerated>:1 +0xa9 go.uber.org/zap/zapcore.(*ioCore).Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zapcore/core.go:90 +0x1c3 go.uber.org/zap/zapcore.(*CheckedEntry).Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zapcore/entry.go:215 +0x1e7 go.uber.org/zap.(*Logger).Info() /go/pkg/mod/go.uber.org/zap@v1.10.0/logger.go:187 +0x95 github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).persist() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:720 +0x6bb github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).Run.func2() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:228 +0x53 Previous write at 0x00c00015a843 by goroutine 98: testing.tRunner.func1() /usr/local/go/src/testing/testing.go:900 +0x353 testing.tRunner() /usr/local/go/src/testing/testing.go:913 +0x1bb Goroutine 112 (running) created at: github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).Run() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:227 +0x264 Goroutine 98 (finished) created at: testing.(*T).Run() /usr/local/go/src/testing/testing.go:960 +0x651 testing.runTests.func1() /usr/local/go/src/testing/testing.go:1202 +0xa6 testing.tRunner() /usr/local/go/src/testing/testing.go:909 +0x199 testing.runTests() /usr/local/go/src/testing/testing.go:1200 +0x521 testing.(*M).Run() /usr/local/go/src/testing/testing.go:1117 +0x2ff main.main() _testmain.go:162 +0x337 ================== --- FAIL: TestService_OnPayload (4.11s)
2020-01-20 16:40:52 +00:00
srv.Chain.Close()
2019-12-27 11:09:58 +00:00
}
func TestService_OnPayload(t *testing.T) {
srv := newTestService(t)
consensus: prevent synchronization stalls When CN is not up to date with the network is synchonizes blocks first and only then starts consensus process. But while synchronizing it receives consensus payloads and tries to process them even though messages reader routine is not started yet. This leads to lots of goroutines waiting to send their messages: Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639919 [chan send, 4 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc005bd7680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc00507d170, 0xc005bdd560, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc00507d170) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 1639181 [chan send, 10 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc013bb6600) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc01361ee10, 0xc01342c780, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc01361ee10) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Jun 25 23:55:53 nodoka neo-go[32733]: goroutine 39454 [chan send, 32 minutes]: Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/consensus.(*service).OnPayload(0xc0000ecb40, 0xc014fea680) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/consensus/consensus.go:329 +0x31b Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleConsensusCmd(...) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:687 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*Server).handleMessage(0xc0000ba160, 0x1053260, 0xc0140b2ea0, 0xc014fe0ed0, 0x0, 0x0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/server.go:806 +0xd58 Jun 25 23:55:53 nodoka neo-go[32733]: github.com/nspcc-dev/neo-go/pkg/network.(*TCPPeer).handleConn(0xc0140b2ea0) Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_peer.go:160 +0x294 Jun 25 23:55:53 nodoka neo-go[32733]: created by github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Dial Jun 25 23:55:53 nodoka neo-go[32733]: #011/go/src/github.com/nspcc-dev/neo-go/pkg/network/tcp_transport.go:38 +0x1ad Luckily it doesn't break synchronization completely as eventually connection timers fire, the node breaks all connections, create new ones and these new ones request blocks successfully until another consensus payload stalls them too. In the end the node reaches synchronization, message processing loop starts and releases all of these waiting goroutines, but it's better for us to avoid this happening at all. This also makes double-starting a no-op which is a nice property.
2020-06-26 08:19:01 +00:00
// This test directly reads things from srv.messages that normally
// is read by internal goroutine started with Start(). So let's
// pretend we really did start already.
srv.started.Store(true)
priv, _ := getTestValidator(1)
p := new(Payload)
p.message = &message{}
p.SetValidatorIndex(1)
p.SetPayload(&prepareRequest{})
// payload is not signed
srv.OnPayload(p)
shouldNotReceive(t, srv.messages)
require.Nil(t, srv.GetPayload(p.Hash()))
require.NoError(t, p.Sign(priv))
srv.OnPayload(p)
shouldReceive(t, srv.messages)
require.Equal(t, p, srv.GetPayload(p.Hash()))
// payload has already been received
srv.OnPayload(p)
shouldNotReceive(t, srv.messages)
consensus: close chain in tests Avoid test failures like this one: === RUN TestService_OnPayload ================== WARNING: DATA RACE Read at 0x00c00015a843 by goroutine 112: testing.(*common).logDepth() /usr/local/go/src/testing/testing.go:665 +0xa1 testing.(*common).Logf() /usr/local/go/src/testing/testing.go:658 +0x8f testing.(*T).Logf() <autogenerated>:1 +0x75 go.uber.org/zap/zaptest.testingWriter.Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zaptest/logger.go:130 +0x11f go.uber.org/zap/zaptest.(*testingWriter).Write() <autogenerated>:1 +0xa9 go.uber.org/zap/zapcore.(*ioCore).Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zapcore/core.go:90 +0x1c3 go.uber.org/zap/zapcore.(*CheckedEntry).Write() /go/pkg/mod/go.uber.org/zap@v1.10.0/zapcore/entry.go:215 +0x1e7 go.uber.org/zap.(*Logger).Info() /go/pkg/mod/go.uber.org/zap@v1.10.0/logger.go:187 +0x95 github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).persist() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:720 +0x6bb github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).Run.func2() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:228 +0x53 Previous write at 0x00c00015a843 by goroutine 98: testing.tRunner.func1() /usr/local/go/src/testing/testing.go:900 +0x353 testing.tRunner() /usr/local/go/src/testing/testing.go:913 +0x1bb Goroutine 112 (running) created at: github.com/CityOfZion/neo-go/pkg/core.(*Blockchain).Run() /go/src/github.com/CityOfZion/neo-go/pkg/core/blockchain.go:227 +0x264 Goroutine 98 (finished) created at: testing.(*T).Run() /usr/local/go/src/testing/testing.go:960 +0x651 testing.runTests.func1() /usr/local/go/src/testing/testing.go:1202 +0xa6 testing.tRunner() /usr/local/go/src/testing/testing.go:909 +0x199 testing.runTests() /usr/local/go/src/testing/testing.go:1200 +0x521 testing.(*M).Run() /usr/local/go/src/testing/testing.go:1117 +0x2ff main.main() _testmain.go:162 +0x337 ================== --- FAIL: TestService_OnPayload (4.11s)
2020-01-20 16:40:52 +00:00
srv.Chain.Close()
}
func shouldReceive(t *testing.T, ch chan Payload) {
select {
case <-ch:
default:
require.Fail(t, "missing expected message")
}
}
func shouldNotReceive(t *testing.T, ch chan Payload) {
select {
case <-ch:
require.Fail(t, "unexpected message receive")
default:
}
}
func newTestService(t *testing.T) *service {
srv, err := NewService(Config{
2019-12-30 07:43:05 +00:00
Logger: zaptest.NewLogger(t),
Broadcast: func(*Payload) {},
Chain: newTestChain(t),
RequestTx: func(...util.Uint256) {},
Wallet: &config.Wallet{
2020-01-15 14:05:47 +00:00
Path: "./testdata/wallet1.json",
Password: "one",
},
})
require.NoError(t, err)
return srv.(*service)
}
func getTestValidator(i int) (*privateKey, *publicKey) {
key := testchain.PrivateKeyByID(i)
2020-01-15 14:05:47 +00:00
return &privateKey{PrivateKey: key}, &publicKey{PublicKey: key.PublicKey()}
}
func newTestChain(t *testing.T) *core.Blockchain {
unitTestNetCfg, err := config.Load("../../config", netmode.UnitTestNet)
require.NoError(t, err)
2019-12-30 07:43:05 +00:00
chain, err := core.NewBlockchain(storage.NewMemoryStore(), unitTestNetCfg.ProtocolConfiguration, zaptest.NewLogger(t))
require.NoError(t, err)
go chain.Run()
return chain
}
2020-04-21 15:09:34 +00:00
var neoOwner = testchain.MultisigScriptHash()
func addSender(t *testing.T, txs ...*transaction.Transaction) {
for _, tx := range txs {
2020-04-21 15:09:34 +00:00
tx.Sender = neoOwner
}
}
func signTx(t *testing.T, feePerByte int64, txs ...*transaction.Transaction) {
validators := make([]*keys.PublicKey, 4)
privNetKeys := make([]*keys.PrivateKey, 4)
for i := 0; i < 4; i++ {
privNetKeys[i] = testchain.PrivateKey(i)
validators[i] = privNetKeys[i].PublicKey()
}
privNetKeys = privNetKeys[:3]
rawScript, err := smartcontract.CreateMultiSigRedeemScript(3, validators)
require.NoError(t, err)
for _, tx := range txs {
size := io.GetVarSize(tx)
netFee, sizeDelta := core.CalculateNetworkFee(rawScript)
tx.NetworkFee += +netFee
size += sizeDelta
tx.NetworkFee += int64(size) * feePerByte
data := tx.GetSignedPart()
2020-04-21 13:45:48 +00:00
buf := io.NewBufBinWriter()
for _, key := range privNetKeys {
signature := key.Sign(data)
2020-04-21 13:45:48 +00:00
emit.Bytes(buf.BinWriter, signature)
}
tx.Scripts = []transaction.Witness{{
2020-04-21 13:45:48 +00:00
InvocationScript: buf.Bytes(),
VerificationScript: rawScript,
}}
}
}