2015-12-22 22:27:40 -08:00
|
|
|
package consensus
|
|
|
|
|
|
|
|
import (
|
|
|
|
"bufio"
|
|
|
|
"errors"
|
|
|
|
"fmt"
|
2016-01-10 20:31:05 -08:00
|
|
|
"io"
|
2015-12-22 22:27:40 -08:00
|
|
|
"os"
|
|
|
|
"reflect"
|
|
|
|
"strconv"
|
|
|
|
"strings"
|
|
|
|
"time"
|
|
|
|
|
2015-12-22 20:24:15 -08:00
|
|
|
. "github.com/tendermint/go-common"
|
|
|
|
"github.com/tendermint/go-wire"
|
2015-12-22 22:27:40 -08:00
|
|
|
|
|
|
|
sm "github.com/tendermint/tendermint/state"
|
|
|
|
"github.com/tendermint/tendermint/types"
|
|
|
|
)
|
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
// unmarshal and apply a single message to the consensus state
|
|
|
|
func (cs *ConsensusState) readReplayMessage(msgBytes []byte, newStepCh chan interface{}) error {
|
|
|
|
var err error
|
|
|
|
var msg ConsensusLogMessage
|
|
|
|
wire.ReadJSON(&msg, msgBytes, &err)
|
|
|
|
if err != nil {
|
2016-02-02 20:05:24 -08:00
|
|
|
fmt.Println("MsgBytes:", msgBytes, string(msgBytes))
|
2016-01-18 11:10:05 -08:00
|
|
|
return fmt.Errorf("Error reading json data: %v", err)
|
|
|
|
}
|
2015-12-22 22:27:40 -08:00
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
// for logging
|
|
|
|
switch m := msg.Msg.(type) {
|
2016-01-28 19:53:22 -08:00
|
|
|
case types.EventDataRoundState:
|
2016-01-18 11:10:05 -08:00
|
|
|
log.Notice("New Step", "height", m.Height, "round", m.Round, "step", m.Step)
|
|
|
|
// these are playback checks
|
|
|
|
ticker := time.After(time.Second * 2)
|
|
|
|
if newStepCh != nil {
|
|
|
|
select {
|
|
|
|
case mi := <-newStepCh:
|
2016-01-28 19:53:22 -08:00
|
|
|
m2 := mi.(types.EventDataRoundState)
|
2016-01-18 11:10:05 -08:00
|
|
|
if m.Height != m2.Height || m.Round != m2.Round || m.Step != m2.Step {
|
|
|
|
return fmt.Errorf("RoundState mismatch. Got %v; Expected %v", m2, m)
|
|
|
|
}
|
|
|
|
case <-ticker:
|
|
|
|
return fmt.Errorf("Failed to read off newStepCh")
|
|
|
|
}
|
|
|
|
}
|
|
|
|
case msgInfo:
|
|
|
|
peerKey := m.PeerKey
|
|
|
|
if peerKey == "" {
|
|
|
|
peerKey = "local"
|
|
|
|
}
|
|
|
|
switch msg := m.Msg.(type) {
|
|
|
|
case *ProposalMessage:
|
|
|
|
p := msg.Proposal
|
|
|
|
log.Notice("Proposal", "height", p.Height, "round", p.Round, "header",
|
|
|
|
p.BlockPartsHeader, "pol", p.POLRound, "peer", peerKey)
|
|
|
|
case *BlockPartMessage:
|
|
|
|
log.Notice("BlockPart", "height", msg.Height, "round", msg.Round, "peer", peerKey)
|
|
|
|
case *VoteMessage:
|
|
|
|
v := msg.Vote
|
|
|
|
log.Notice("Vote", "height", v.Height, "round", v.Round, "type", v.Type,
|
|
|
|
"hash", v.BlockHash, "header", v.BlockPartsHeader, "peer", peerKey)
|
2015-12-22 22:27:40 -08:00
|
|
|
}
|
2016-01-18 11:10:05 -08:00
|
|
|
// internal or from peer
|
|
|
|
if m.PeerKey == "" {
|
|
|
|
cs.internalMsgQueue <- m
|
|
|
|
} else {
|
|
|
|
cs.peerMsgQueue <- m
|
|
|
|
}
|
|
|
|
case timeoutInfo:
|
|
|
|
log.Notice("Timeout", "height", m.Height, "round", m.Round, "step", m.Step, "dur", m.Duration)
|
|
|
|
cs.tockChan <- m
|
|
|
|
default:
|
|
|
|
return fmt.Errorf("Unknown ConsensusLogMessage type: %v", reflect.TypeOf(msg.Msg))
|
2015-12-22 22:27:40 -08:00
|
|
|
}
|
2016-01-18 11:10:05 -08:00
|
|
|
return nil
|
2015-12-22 22:27:40 -08:00
|
|
|
}
|
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
// replay only those messages since the last block
|
2016-01-10 20:31:05 -08:00
|
|
|
func (cs *ConsensusState) catchupReplay(height int) error {
|
2016-01-18 11:10:05 -08:00
|
|
|
if cs.wal == nil {
|
|
|
|
log.Warn("consensus msg log is nil")
|
2016-01-10 20:31:05 -08:00
|
|
|
return nil
|
|
|
|
}
|
2016-01-18 11:10:05 -08:00
|
|
|
if !cs.wal.exists {
|
|
|
|
// new wal, nothing to catchup on
|
2016-01-10 20:31:05 -08:00
|
|
|
return nil
|
|
|
|
}
|
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
// starting from end of file,
|
|
|
|
// read messages until a new height is found
|
|
|
|
nLines, err := cs.wal.SeekFromEnd(func(lineBytes []byte) bool {
|
2016-01-10 20:31:05 -08:00
|
|
|
var err error
|
|
|
|
var msg ConsensusLogMessage
|
|
|
|
wire.ReadJSON(&msg, lineBytes, &err)
|
|
|
|
if err != nil {
|
|
|
|
panic(Fmt("Failed to read cs_msg_log json: %v", err))
|
|
|
|
}
|
2016-01-28 19:53:22 -08:00
|
|
|
m, ok := msg.Msg.(types.EventDataRoundState)
|
2016-01-10 20:31:05 -08:00
|
|
|
if ok && m.Step == RoundStepNewHeight.String() {
|
|
|
|
// TODO: ensure the height matches
|
|
|
|
return true
|
|
|
|
}
|
|
|
|
return false
|
|
|
|
})
|
|
|
|
|
|
|
|
if err != nil {
|
|
|
|
return err
|
|
|
|
}
|
|
|
|
|
2016-01-18 12:57:57 -08:00
|
|
|
var beginning bool // if we had to go back to the beginning
|
|
|
|
if c, _ := cs.wal.fp.Seek(0, 1); c == 0 {
|
|
|
|
beginning = true
|
|
|
|
}
|
|
|
|
|
|
|
|
log.Notice("Catchup by replaying consensus messages", "n", nLines)
|
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
// now we can replay the latest nLines on consensus state
|
|
|
|
// note we can't use scan because we've already been reading from the file
|
|
|
|
reader := bufio.NewReader(cs.wal.fp)
|
|
|
|
for i := 0; i < nLines; i++ {
|
2016-01-10 20:31:05 -08:00
|
|
|
msgBytes, err := reader.ReadBytes('\n')
|
|
|
|
if err == io.EOF {
|
|
|
|
break
|
|
|
|
} else if err != nil {
|
|
|
|
return err
|
|
|
|
} else if len(msgBytes) == 0 {
|
|
|
|
continue
|
2016-02-02 20:05:24 -08:00
|
|
|
} else if len(msgBytes) == 1 && msgBytes[0] == '\n' {
|
|
|
|
continue
|
2016-01-10 20:31:05 -08:00
|
|
|
}
|
2016-02-29 15:02:22 -08:00
|
|
|
// the first msg is the NewHeight event (if we're not at the beginning), so we can ignore it
|
2016-01-18 12:57:57 -08:00
|
|
|
if !beginning && i == 1 {
|
2016-01-10 20:31:05 -08:00
|
|
|
continue
|
|
|
|
}
|
|
|
|
|
|
|
|
// NOTE: since the priv key is set when the msgs are received
|
|
|
|
// it will attempt to eg double sign but we can just ignore it
|
|
|
|
// since the votes will be replayed and we'll get to the next step
|
2016-01-18 11:10:05 -08:00
|
|
|
if err := cs.readReplayMessage(msgBytes, nil); err != nil {
|
2016-01-10 20:31:05 -08:00
|
|
|
return err
|
|
|
|
}
|
|
|
|
}
|
2016-01-18 12:57:57 -08:00
|
|
|
log.Info("Done catchup replay")
|
2016-01-10 20:31:05 -08:00
|
|
|
return nil
|
2016-01-18 11:10:05 -08:00
|
|
|
}
|
|
|
|
|
|
|
|
//--------------------------------------------------------
|
|
|
|
// replay messages interactively or all at once
|
|
|
|
|
|
|
|
// Interactive playback
|
|
|
|
func (cs ConsensusState) ReplayConsole(file string) error {
|
|
|
|
return cs.replay(file, true)
|
|
|
|
}
|
2016-01-10 20:31:05 -08:00
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
// Full playback, with tests
|
|
|
|
func (cs ConsensusState) ReplayMessages(file string) error {
|
|
|
|
return cs.replay(file, false)
|
2016-01-10 20:31:05 -08:00
|
|
|
}
|
|
|
|
|
2016-01-06 15:42:12 -08:00
|
|
|
// replay all msgs or start the console
|
|
|
|
func (cs *ConsensusState) replay(file string, console bool) error {
|
|
|
|
if cs.IsRunning() {
|
|
|
|
return errors.New("cs is already running, cannot replay")
|
|
|
|
}
|
2016-01-18 11:10:05 -08:00
|
|
|
if cs.wal != nil {
|
|
|
|
return errors.New("cs wal is open, cannot replay")
|
|
|
|
}
|
2016-01-06 15:42:12 -08:00
|
|
|
|
|
|
|
cs.startForReplay()
|
|
|
|
|
|
|
|
// ensure all new step events are regenerated as expected
|
2016-01-28 19:53:22 -08:00
|
|
|
newStepCh := subscribeToEvent(cs.evsw, "replay-test", types.EventStringNewRoundStep(), 1)
|
2016-01-06 15:42:12 -08:00
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
// just open the file for reading, no need to use wal
|
2016-01-06 15:42:12 -08:00
|
|
|
fp, err := os.OpenFile(file, os.O_RDONLY, 0666)
|
|
|
|
if err != nil {
|
|
|
|
return err
|
|
|
|
}
|
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
pb := newPlayback(file, fp, cs, cs.state.Copy())
|
2016-01-06 15:42:12 -08:00
|
|
|
defer pb.fp.Close()
|
|
|
|
|
|
|
|
var nextN int // apply N msgs in a row
|
|
|
|
for pb.scanner.Scan() {
|
|
|
|
if nextN == 0 && console {
|
|
|
|
nextN = pb.replayConsoleLoop()
|
|
|
|
}
|
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
if err := pb.cs.readReplayMessage(pb.scanner.Bytes(), newStepCh); err != nil {
|
2016-01-06 15:42:12 -08:00
|
|
|
return err
|
|
|
|
}
|
|
|
|
|
|
|
|
if nextN > 0 {
|
|
|
|
nextN -= 1
|
|
|
|
}
|
|
|
|
pb.count += 1
|
|
|
|
}
|
|
|
|
return nil
|
|
|
|
}
|
|
|
|
|
|
|
|
//------------------------------------------------
|
|
|
|
// playback manager
|
|
|
|
|
2015-12-22 22:27:40 -08:00
|
|
|
type playback struct {
|
2016-01-18 11:10:05 -08:00
|
|
|
cs *ConsensusState
|
|
|
|
|
|
|
|
fp *os.File
|
|
|
|
scanner *bufio.Scanner
|
|
|
|
count int // how many lines/msgs into the file are we
|
|
|
|
|
|
|
|
// replays can be reset to beginning
|
|
|
|
fileName string // so we can close/reopen the file
|
|
|
|
genesisState *sm.State // so the replay session knows where to restart from
|
2015-12-22 22:27:40 -08:00
|
|
|
}
|
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
func newPlayback(fileName string, fp *os.File, cs *ConsensusState, genState *sm.State) *playback {
|
2015-12-22 22:27:40 -08:00
|
|
|
return &playback{
|
|
|
|
cs: cs,
|
|
|
|
fp: fp,
|
2016-01-18 11:10:05 -08:00
|
|
|
fileName: fileName,
|
|
|
|
genesisState: genState,
|
2015-12-22 22:27:40 -08:00
|
|
|
scanner: bufio.NewScanner(fp),
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2016-01-06 15:42:12 -08:00
|
|
|
// go back count steps by resetting the state and running (pb.count - count) steps
|
2016-01-18 11:10:05 -08:00
|
|
|
func (pb *playback) replayReset(count int, newStepCh chan interface{}) error {
|
2015-12-22 22:27:40 -08:00
|
|
|
|
|
|
|
pb.cs.Stop()
|
|
|
|
|
2016-05-08 15:00:58 -07:00
|
|
|
newCS := NewConsensusState(pb.cs.config, pb.genesisState.Copy(), pb.cs.proxyAppConn, pb.cs.blockStore, pb.cs.mempool)
|
|
|
|
newCS.SetEventSwitch(pb.cs.evsw)
|
|
|
|
newCS.startForReplay()
|
2015-12-22 22:27:40 -08:00
|
|
|
|
|
|
|
pb.fp.Close()
|
2016-01-18 11:10:05 -08:00
|
|
|
fp, err := os.OpenFile(pb.fileName, os.O_RDONLY, 0666)
|
2015-12-22 22:27:40 -08:00
|
|
|
if err != nil {
|
|
|
|
return err
|
|
|
|
}
|
|
|
|
pb.fp = fp
|
|
|
|
pb.scanner = bufio.NewScanner(fp)
|
|
|
|
count = pb.count - count
|
|
|
|
log.Notice(Fmt("Reseting from %d to %d", pb.count, count))
|
|
|
|
pb.count = 0
|
2016-05-08 15:00:58 -07:00
|
|
|
pb.cs = newCS
|
2015-12-22 22:27:40 -08:00
|
|
|
for i := 0; pb.scanner.Scan() && i < count; i++ {
|
2016-01-18 11:10:05 -08:00
|
|
|
if err := pb.cs.readReplayMessage(pb.scanner.Bytes(), newStepCh); err != nil {
|
2015-12-22 22:27:40 -08:00
|
|
|
return err
|
|
|
|
}
|
|
|
|
pb.count += 1
|
|
|
|
}
|
|
|
|
return nil
|
|
|
|
}
|
|
|
|
|
2015-12-23 18:43:28 -08:00
|
|
|
func (cs *ConsensusState) startForReplay() {
|
|
|
|
cs.BaseService.OnStart()
|
|
|
|
go cs.receiveRoutine(0)
|
|
|
|
// since we replay tocks we just ignore ticks
|
|
|
|
go func() {
|
|
|
|
for {
|
|
|
|
select {
|
|
|
|
case <-cs.tickChan:
|
|
|
|
case <-cs.Quit:
|
|
|
|
return
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}()
|
|
|
|
}
|
|
|
|
|
2016-01-06 15:42:12 -08:00
|
|
|
// console function for parsing input and running commands
|
2015-12-22 22:27:40 -08:00
|
|
|
func (pb *playback) replayConsoleLoop() int {
|
|
|
|
for {
|
|
|
|
fmt.Printf("> ")
|
|
|
|
bufReader := bufio.NewReader(os.Stdin)
|
|
|
|
line, more, err := bufReader.ReadLine()
|
|
|
|
if more {
|
|
|
|
Exit("input is too long")
|
|
|
|
} else if err != nil {
|
|
|
|
Exit(err.Error())
|
|
|
|
}
|
|
|
|
|
|
|
|
tokens := strings.Split(string(line), " ")
|
|
|
|
if len(tokens) == 0 {
|
|
|
|
continue
|
|
|
|
}
|
|
|
|
|
|
|
|
switch tokens[0] {
|
|
|
|
case "next":
|
|
|
|
// "next" -> replay next message
|
|
|
|
// "next N" -> replay next N messages
|
|
|
|
|
|
|
|
if len(tokens) == 1 {
|
|
|
|
return 0
|
|
|
|
} else {
|
|
|
|
i, err := strconv.Atoi(tokens[1])
|
|
|
|
if err != nil {
|
|
|
|
fmt.Println("next takes an integer argument")
|
|
|
|
} else {
|
|
|
|
return i
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
case "back":
|
|
|
|
// "back" -> go back one message
|
|
|
|
// "back N" -> go back N messages
|
|
|
|
|
|
|
|
// NOTE: "back" is not supported in the state machine design,
|
2016-01-06 15:42:12 -08:00
|
|
|
// so we restart and replay up to
|
2015-12-22 22:27:40 -08:00
|
|
|
|
2016-01-18 11:10:05 -08:00
|
|
|
// ensure all new step events are regenerated as expected
|
2016-01-28 19:53:22 -08:00
|
|
|
newStepCh := subscribeToEvent(pb.cs.evsw, "replay-test", types.EventStringNewRoundStep(), 1)
|
2015-12-22 22:27:40 -08:00
|
|
|
if len(tokens) == 1 {
|
2016-01-18 11:10:05 -08:00
|
|
|
pb.replayReset(1, newStepCh)
|
2015-12-22 22:27:40 -08:00
|
|
|
} else {
|
|
|
|
i, err := strconv.Atoi(tokens[1])
|
|
|
|
if err != nil {
|
|
|
|
fmt.Println("back takes an integer argument")
|
|
|
|
} else if i > pb.count {
|
|
|
|
fmt.Printf("argument to back must not be larger than the current count (%d)\n", pb.count)
|
|
|
|
} else {
|
2016-01-18 11:10:05 -08:00
|
|
|
pb.replayReset(i, newStepCh)
|
2015-12-22 22:27:40 -08:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
case "rs":
|
|
|
|
// "rs" -> print entire round state
|
|
|
|
// "rs short" -> print height/round/step
|
|
|
|
// "rs <field>" -> print another field of the round state
|
|
|
|
|
|
|
|
rs := pb.cs.RoundState
|
|
|
|
if len(tokens) == 1 {
|
|
|
|
fmt.Println(rs)
|
|
|
|
} else {
|
|
|
|
switch tokens[1] {
|
|
|
|
case "short":
|
|
|
|
fmt.Printf("%v/%v/%v\n", rs.Height, rs.Round, rs.Step)
|
|
|
|
case "validators":
|
|
|
|
fmt.Println(rs.Validators)
|
|
|
|
case "proposal":
|
|
|
|
fmt.Println(rs.Proposal)
|
|
|
|
case "proposal_block":
|
|
|
|
fmt.Printf("%v %v\n", rs.ProposalBlockParts.StringShort(), rs.ProposalBlock.StringShort())
|
|
|
|
case "locked_round":
|
|
|
|
fmt.Println(rs.LockedRound)
|
|
|
|
case "locked_block":
|
|
|
|
fmt.Printf("%v %v\n", rs.LockedBlockParts.StringShort(), rs.LockedBlock.StringShort())
|
|
|
|
case "votes":
|
|
|
|
fmt.Println(rs.Votes.StringIndented(" "))
|
|
|
|
|
|
|
|
default:
|
|
|
|
fmt.Println("Unknown option", tokens[1])
|
|
|
|
}
|
|
|
|
}
|
2015-12-23 18:43:28 -08:00
|
|
|
case "n":
|
|
|
|
fmt.Println(pb.count)
|
2015-12-22 22:27:40 -08:00
|
|
|
}
|
|
|
|
}
|
|
|
|
return 0
|
|
|
|
}
|