Add logs to lite/*; Fix rpc status to return consensus height, not blockstore height

.gitignore

@@ -27,3 +27,4 @@ scripts/cutWALUntil/cutWALUntil
 
 libs/pubsub/query/fuzz_test/output
 shunit2
+.tendermint-lite

cmd/tendermint/commands/lite.go

@@ -6,10 +6,9 @@ import (
 
 	"github.com/spf13/cobra"
 
-	cmn "github.com/tendermint/tmlibs/common"
-
 	"github.com/tendermint/tendermint/lite/proxy"
 	rpcclient "github.com/tendermint/tendermint/rpc/client"
+	cmn "github.com/tendermint/tmlibs/common"
 )
 
 // LiteCmd represents the base command when called without any subcommands
@@ -66,17 +65,21 @@ func runProxy(cmd *cobra.Command, args []string) error {
 	}
 
 	// First, connect a client
+	logger.Info("Connecting to source HTTP client...")
 	node := rpcclient.NewHTTP(nodeAddr, "/websocket")
 
-	cert, err := proxy.GetCertifier(chainID, home, node)
+	logger.Info("Constructing certifier...")
+	cert, err := proxy.NewCertifier(chainID, home, node, logger)
 	if err != nil {
-		return err
+		return cmn.ErrorWrap(err, "constructing certifier")
 	}
+	cert.SetLogger(logger)
 	sc := proxy.SecureClient(node, cert)
 
+	logger.Info("Starting proxy...")
 	err = proxy.StartProxy(sc, listenAddr, logger)
 	if err != nil {
-		return err
+		return cmn.ErrorWrap(err, "starting proxy")
 	}
 
 	cmn.TrapSignal(func() {

consensus/state.go

@@ -196,6 +196,15 @@ func (cs *ConsensusState) GetState() sm.State {
 	return cs.state.Copy()
 }
 
+// GetLastHeight returns the last height committed.
+// If there were no blocks, returns 0.
+func (cs *ConsensusState) GetLastHeight() int64 {
+	cs.mtx.Lock()
+	defer cs.mtx.Unlock()
+
+	return cs.RoundState.Height - 1
+}
+
 // GetRoundState returns a shallow copy of the internal consensus state.
 func (cs *ConsensusState) GetRoundState() *cstypes.RoundState {
 	cs.mtx.Lock()

lite/client/provider.go

@@ -8,12 +8,12 @@ package client
 import (
 	"fmt"
 
+	"github.com/tendermint/tendermint/lite"
+	lerr "github.com/tendermint/tendermint/lite/errors"
 	rpcclient "github.com/tendermint/tendermint/rpc/client"
 	ctypes "github.com/tendermint/tendermint/rpc/core/types"
 	"github.com/tendermint/tendermint/types"
-
-	"github.com/tendermint/tendermint/lite"
-	lerr "github.com/tendermint/tendermint/lite/errors"
+	log "github.com/tendermint/tmlibs/log"
 )
 
 // SignStatusClient combines a SignClient and StatusClient.
@@ -23,22 +23,30 @@ type SignStatusClient interface {
 }
 
 type provider struct {
+	logger  log.Logger
 	chainID string
 	client  SignStatusClient
 }
 
 // NewProvider implements Provider (but not PersistentProvider).
 func NewProvider(chainID string, client SignStatusClient) lite.Provider {
-	return &provider{chainID: chainID, client: client}
+	return &provider{
+		logger:  log.NewNopLogger(),
+		chainID: chainID,
+		client:  client,
+	}
 }
 
 // NewHTTPProvider can connect to a tendermint json-rpc endpoint
 // at the given url, and uses that as a read-only provider.
 func NewHTTPProvider(chainID, remote string) lite.Provider {
-	return &provider{
-		chainID: chainID,
-		client:  rpcclient.NewHTTP(remote, "/websocket"),
-	}
+	return NewProvider(chainID, rpcclient.NewHTTP(remote, "/websocket"))
+}
+
+// Implements Provider.
+func (p *provider) SetLogger(logger log.Logger) {
+	logger = logger.With("module", "lite/client")
+	p.logger = logger
 }
 
 // StatusClient returns the internal client as a StatusClient

lite/dbprovider.go

@@ -10,23 +10,34 @@ import (
 	lerr "github.com/tendermint/tendermint/lite/errors"
 	"github.com/tendermint/tendermint/types"
 	dbm "github.com/tendermint/tmlibs/db"
+	log "github.com/tendermint/tmlibs/log"
 )
 
 type DBProvider struct {
-	chainID string
-	db      dbm.DB
-	cdc     *amino.Codec
-	limit   int
+	logger log.Logger
+	label  string
+	db     dbm.DB
+	cdc    *amino.Codec
+	limit  int
 }
 
-func NewDBProvider(db dbm.DB) *DBProvider {
+func NewDBProvider(label string, db dbm.DB) *DBProvider {
 	//db = dbm.NewDebugDB("db provider "+cmn.RandStr(4), db)
 	cdc := amino.NewCodec()
 	crypto.RegisterAmino(cdc)
-	dbp := &DBProvider{db: db, cdc: cdc}
+	dbp := &DBProvider{
+		logger: log.NewNopLogger(),
+		label:  label,
+		db:     db,
+		cdc:    cdc,
+	}
 	return dbp
 }
 
+func (dbp *DBProvider) SetLogger(logger log.Logger) {
+	dbp.logger = logger.With("label", dbp.label)
+}
+
 func (dbp *DBProvider) SetLimit(limit int) *DBProvider {
 	dbp.limit = limit
 	return dbp
@@ -35,6 +46,7 @@ func (dbp *DBProvider) SetLimit(limit int) *DBProvider {
 // Implements PersistentProvider.
 func (dbp *DBProvider) SaveFullCommit(fc FullCommit) error {
 
+	dbp.logger.Info("DBProvider.SaveFullCommit()...", "fc", fc)
 	batch := dbp.db.NewBatch()
 
 	// Save the fc.validators.
@@ -79,6 +91,9 @@ func (dbp *DBProvider) SaveFullCommit(fc FullCommit) error {
 func (dbp *DBProvider) LatestFullCommit(chainID string, minHeight, maxHeight int64) (
 	FullCommit, error) {
 
+	dbp.logger.Info("DBProvider.LatestFullCommit()...",
+		"chainID", chainID, "minHeight", minHeight, "maxHeight", maxHeight)
+
 	if minHeight <= 0 {
 		minHeight = 1
 	}
@@ -107,7 +122,15 @@ func (dbp *DBProvider) LatestFullCommit(chainID string, minHeight, maxHeight int
 			if err != nil {
 				return FullCommit{}, err
 			} else {
-				return dbp.fillFullCommit(sh)
+				lfc, err := dbp.fillFullCommit(sh)
+				if err == nil {
+					dbp.logger.Info("DBProvider.LatestFullCommit() found latest.", "height", lfc.Height())
+					return lfc, nil
+				} else {
+					dbp.logger.Info("DBProvider.LatestFullCommit() got error", "lfc", lfc)
+					dbp.logger.Info(fmt.Sprintf("%+v", err))
+					return lfc, err
+				}
 			}
 		}
 	}
@@ -155,6 +178,9 @@ func (dbp *DBProvider) fillFullCommit(sh types.SignedHeader) (FullCommit, error)
 }
 
 func (dbp *DBProvider) deleteAfterN(chainID string, after int) error {
+
+	dbp.logger.Info("DBProvider.deleteAfterN()...", "chainID", chainID, "after", after)
+
 	itr := dbp.db.ReverseIterator(
 		signedHeaderKey(chainID, 1<<63-1),
 		signedHeaderKey(chainID, 0),
@@ -163,6 +189,7 @@ func (dbp *DBProvider) deleteAfterN(chainID string, after int) error {
 
 	var lastHeight int64 = 1<<63 - 1
 	var numSeen = 0
+	var numDeleted = 0
 
 	for itr.Valid() {
 		key := itr.Key()
@@ -176,9 +203,13 @@ func (dbp *DBProvider) deleteAfterN(chainID string, after int) error {
 			}
 			if numSeen > after {
 				dbp.db.Delete(key)
+				numDeleted += 1
 			}
 		}
+		itr.Next()
 	}
+
+	dbp.logger.Info(fmt.Sprintf("DBProvider.deleteAfterN() deleted %v items\n", numDeleted))
 	return nil
 }
 

lite/doc.go

@@ -92,8 +92,9 @@ type PersistentProvider interface {
 * MultiProvider - combine multiple providers.
 
 The suggested use for local light clients is client.NewHTTPProvider(...) for
-getting new data (Source), and NewMultiProvider(NewDBProvider(dbm.NewMemDB()),
-NewDBProvider(db.NewFileDB(...))) to store confirmed full commits (Trusted)
+getting new data (Source), and NewMultiProvider(NewDBProvider("label",
+dbm.NewMemDB()), NewDBProvider("label", db.NewFileDB(...))) to store confirmed
+full commits (Trusted)
 
 
 # How We Track Validators

lite/inquiring_certifier.go

@@ -3,9 +3,9 @@ package lite
 import (
 	"bytes"
 
-	"github.com/tendermint/tendermint/types"
-
 	lerr "github.com/tendermint/tendermint/lite/errors"
+	"github.com/tendermint/tendermint/types"
+	log "github.com/tendermint/tmlibs/log"
 )
 
 var _ Certifier = (*InquiringCertifier)(nil)
@@ -15,6 +15,7 @@ var _ Certifier = (*InquiringCertifier)(nil)
 // validator set changes.  It stores properly validated data on the
 // "trusted" local system.
 type InquiringCertifier struct {
+	logger  log.Logger
 	chainID string
 	// These are only properly validated data, from local system.
 	trusted PersistentProvider
@@ -28,14 +29,20 @@ type InquiringCertifier struct {
 //
 // The trusted provider should a CacheProvider, MemProvider or
 // files.Provider.  The source provider should be a client.HTTPProvider.
-func NewInquiringCertifier(chainID string, trusted PersistentProvider, source Provider) (
-	*InquiringCertifier, error) {
-
+func NewInquiringCertifier(chainID string, trusted PersistentProvider, source Provider) *InquiringCertifier {
 	return &InquiringCertifier{
+		logger:  log.NewNopLogger(),
 		chainID: chainID,
 		trusted: trusted,
 		source:  source,
-	}, nil
+	}
+}
+
+func (ic *InquiringCertifier) SetLogger(logger log.Logger) {
+	logger = logger.With("module", "lite")
+	ic.logger = logger
+	ic.trusted.SetLogger(logger)
+	ic.source.SetLogger(logger)
 }
 
 // Implements Certifier.

lite/inquiring_certifier_test.go

@@ -8,12 +8,13 @@ import (
 	"github.com/stretchr/testify/require"
 
 	dbm "github.com/tendermint/tmlibs/db"
+	log "github.com/tendermint/tmlibs/log"
 )
 
 func TestInquirerValidPath(t *testing.T) {
 	assert, require := assert.New(t), require.New(t)
-	trust := NewDBProvider(dbm.NewMemDB())
-	source := NewDBProvider(dbm.NewMemDB())
+	trust := NewDBProvider("trust", dbm.NewMemDB())
+	source := NewDBProvider("source", dbm.NewMemDB())
 
 	// Set up the validators to generate test blocks.
 	var vote int64 = 10
@@ -43,8 +44,8 @@ func TestInquirerValidPath(t *testing.T) {
 	// Initialize a certifier with the initial state.
 	err := trust.SaveFullCommit(fcz[0])
 	require.Nil(err)
-	cert, err := NewInquiringCertifier(chainID, trust, source)
-	require.Nil(err)
+	cert := NewInquiringCertifier(chainID, trust, source)
+	cert.SetLogger(log.TestingLogger())
 
 	// This should fail validation:
 	sh := fcz[count-1].SignedHeader
@@ -70,8 +71,8 @@ func TestInquirerValidPath(t *testing.T) {
 
 func TestInquirerVerifyHistorical(t *testing.T) {
 	assert, require := assert.New(t), require.New(t)
-	trust := NewDBProvider(dbm.NewMemDB())
-	source := NewDBProvider(dbm.NewMemDB())
+	trust := NewDBProvider("trust", dbm.NewMemDB())
+	source := NewDBProvider("source", dbm.NewMemDB())
 
 	// Set up the validators to generate test blocks.
 	var vote int64 = 10
@@ -101,8 +102,8 @@ func TestInquirerVerifyHistorical(t *testing.T) {
 	// Initialize a certifier with the initial state.
 	err := trust.SaveFullCommit(fcz[0])
 	require.Nil(err)
-	cert, err := NewInquiringCertifier(chainID, trust, source)
-	require.Nil(err)
+	cert := NewInquiringCertifier(chainID, trust, source)
+	cert.SetLogger(log.TestingLogger())
 
 	// Store a few full commits as trust.
 	for _, i := range []int{2, 5} {

lite/multiprovider.go

@@ -3,24 +3,35 @@ package lite
 import (
 	lerr "github.com/tendermint/tendermint/lite/errors"
 	"github.com/tendermint/tendermint/types"
+	log "github.com/tendermint/tmlibs/log"
 )
 
 // multiProvider allows you to place one or more caches in front of a source
 // Provider.  It runs through them in order until a match is found.
 type multiProvider struct {
-	Providers []PersistentProvider
+	logger    log.Logger
+	providers []PersistentProvider
 }
 
 // NewMultiProvider returns a new provider which wraps multiple other providers.
-func NewMultiProvider(providers ...PersistentProvider) multiProvider {
-	return multiProvider{
-		Providers: providers,
+func NewMultiProvider(providers ...PersistentProvider) *multiProvider {
+	return &multiProvider{
+		logger:    log.NewNopLogger(),
+		providers: providers,
+	}
+}
+
+// SetLogger sets logger on self and all subproviders.
+func (mc *multiProvider) SetLogger(logger log.Logger) {
+	mc.logger = logger
+	for _, p := range mc.providers {
+		p.SetLogger(logger)
 	}
 }
 
 // SaveFullCommit saves on all providers, and aborts on the first error.
-func (mc multiProvider) SaveFullCommit(fc FullCommit) (err error) {
-	for _, p := range mc.Providers {
+func (mc *multiProvider) SaveFullCommit(fc FullCommit) (err error) {
+	for _, p := range mc.providers {
 		err = p.SaveFullCommit(fc)
 		if err != nil {
 			return
@@ -32,8 +43,8 @@ func (mc multiProvider) SaveFullCommit(fc FullCommit) (err error) {
 // LatestFullCommit loads the latest from all providers and provides
 // the latest FullCommit that satisfies the conditions.
 // Returns the first error encountered.
-func (mc multiProvider) LatestFullCommit(chainID string, minHeight, maxHeight int64) (fc FullCommit, err error) {
-	for _, p := range mc.Providers {
+func (mc *multiProvider) LatestFullCommit(chainID string, minHeight, maxHeight int64) (fc FullCommit, err error) {
+	for _, p := range mc.providers {
 		var fc_ FullCommit
 		fc_, err = p.LatestFullCommit(chainID, minHeight, maxHeight)
 		if lerr.IsErrCommitNotFound(err) {
@@ -60,8 +71,8 @@ func (mc multiProvider) LatestFullCommit(chainID string, minHeight, maxHeight in
 
 // ValidatorSet returns validator set at height as provided by the first
 // provider which has it, or an error otherwise.
-func (mc multiProvider) ValidatorSet(chainID string, height int64) (valset *types.ValidatorSet, err error) {
-	for _, p := range mc.Providers {
+func (mc *multiProvider) ValidatorSet(chainID string, height int64) (valset *types.ValidatorSet, err error) {
+	for _, p := range mc.providers {
 		valset, err = p.ValidatorSet(chainID, height)
 		if err == nil {
 			// TODO Log unexpected types of errors.

lite/provider.go

@@ -2,6 +2,7 @@ package lite
 
 import (
 	"github.com/tendermint/tendermint/types"
+	log "github.com/tendermint/tmlibs/log"
 )
 
 // Provider provides information for the lite client to sync validators.
@@ -16,6 +17,9 @@ type Provider interface {
 	// Get the valset that corresponds to chainID and height and return.
 	// Height must be >= 1.
 	ValidatorSet(chainID string, height int64) (*types.ValidatorSet, error)
+
+	// Set a logger.
+	SetLogger(logger log.Logger)
 }
 
 // A provider that can also persist new information.

lite/provider_test.go

@@ -10,6 +10,7 @@ import (
 	lerr "github.com/tendermint/tendermint/lite/errors"
 	"github.com/tendermint/tendermint/types"
 	dbm "github.com/tendermint/tmlibs/db"
+	log "github.com/tendermint/tmlibs/log"
 )
 
 // missingProvider doesn't store anything, always a miss.
@@ -28,16 +29,17 @@ func (missingProvider) LatestFullCommit(chainID string, minHeight, maxHeight int
 func (missingProvider) ValidatorSet(chainID string, height int64) (*types.ValidatorSet, error) {
 	return nil, errors.New("missing validator set")
 }
+func (missingProvider) SetLogger(_ log.Logger) {}
 
 func TestMemProvider(t *testing.T) {
-	p := NewDBProvider(dbm.NewMemDB())
+	p := NewDBProvider("mem", dbm.NewMemDB())
 	checkProvider(t, p, "test-mem", "empty")
 }
 
 func TestMultiProvider(t *testing.T) {
 	p := NewMultiProvider(
 		NewMissingProvider(),
-		NewDBProvider(dbm.NewMemDB()),
+		NewDBProvider("mem", dbm.NewMemDB()),
 		NewMissingProvider(),
 	)
 	checkProvider(t, p, "test-cache", "kjfhekfhkewhgit")
@@ -105,8 +107,8 @@ func TestMultiLatestFullCommit(t *testing.T) {
 
 	// We will write data to the second level of the cache (p2), and see what
 	// gets cached/stored in.
-	p := NewDBProvider(dbm.NewMemDB())
-	p2 := NewDBProvider(dbm.NewMemDB())
+	p := NewDBProvider("mem1", dbm.NewMemDB())
+	p2 := NewDBProvider("mem2", dbm.NewMemDB())
 	cp := NewMultiProvider(p, p2)
 
 	chainID := "cache-best-height"

lite/proxy/certifier.go

@@ -3,33 +3,39 @@ package proxy
 import (
 	"github.com/tendermint/tendermint/lite"
 	lclient "github.com/tendermint/tendermint/lite/client"
+	cmn "github.com/tendermint/tmlibs/common"
 	dbm "github.com/tendermint/tmlibs/db"
+	log "github.com/tendermint/tmlibs/log"
 )
 
-func GetCertifier(chainID, rootDir string, client lclient.SignStatusClient) (*lite.InquiringCertifier, error) {
+func NewCertifier(chainID, rootDir string, client lclient.SignStatusClient, logger log.Logger) (*lite.InquiringCertifier, error) {
+
+	logger = logger.With("module", "lite/proxy")
+	logger.Info("lite/proxy/NewCertifier()...", "chainID", chainID, "rootDir", rootDir, "client", client)
+
+	memProvider := lite.NewDBProvider("trusted.mem", dbm.NewMemDB()).SetLimit(10)
+	lvlProvider := lite.NewDBProvider("trusted.lvl", dbm.NewDB("trust-base", dbm.LevelDBBackend, rootDir))
 	trust := lite.NewMultiProvider(
-		lite.NewDBProvider(dbm.NewMemDB()).SetLimit(10),
-		lite.NewDBProvider(dbm.NewDB("trust-base", dbm.LevelDBBackend, rootDir)),
+		memProvider,
+		lvlProvider,
 	)
 	source := lclient.NewProvider(chainID, client)
+	cert := lite.NewInquiringCertifier(chainID, trust, source)
+	cert.SetLogger(logger) // Sets logger recursively.
 
 	// TODO: Make this more secure, e.g. make it interactive in the console?
 	_, err := trust.LatestFullCommit(chainID, 1, 1<<63-1)
 	if err != nil {
+		logger.Info("lite/proxy/NewCertifier found no trusted full commit, initializing from source from height 1...")
 		fc, err := source.LatestFullCommit(chainID, 1, 1)
 		if err != nil {
-			return nil, err
+			return nil, cmn.ErrorWrap(err, "fetching source full commit @ height 1")
 		}
 		err = trust.SaveFullCommit(fc)
 		if err != nil {
-			return nil, err
+			return nil, cmn.ErrorWrap(err, "saving full commit to trusted")
 		}
 	}
 
-	cert, err := lite.NewInquiringCertifier(chainID, trust, source)
-	if err != nil {
-		return nil, err
-	}
-
 	return cert, nil
 }

lite/proxy/wrapper.go

@@ -89,33 +89,49 @@ func (w Wrapper) BlockchainInfo(minHeight, maxHeight int64) (*ctypes.ResultBlock
 
 // Block returns an entire block and verifies all signatures
 func (w Wrapper) Block(height *int64) (*ctypes.ResultBlock, error) {
-	r, err := w.Client.Block(height)
+	resBlock, err := w.Client.Block(height)
 	if err != nil {
 		return nil, err
 	}
 	// get a checkpoint to verify from
-	res, err := w.Commit(height)
+	resCommit, err := w.Commit(height)
 	if err != nil {
 		return nil, err
 	}
-	sh := res.SignedHeader
+	sh := resCommit.SignedHeader
 
 	// now verify
-	err = ValidateBlockMeta(r.BlockMeta, sh)
+	err = ValidateBlockMeta(resBlock.BlockMeta, sh)
 	if err != nil {
 		return nil, err
 	}
-	err = ValidateBlock(r.Block, sh)
+	err = ValidateBlock(resBlock.Block, sh)
 	if err != nil {
 		return nil, err
 	}
-	return r, nil
+	return resBlock, nil
 }
 
 // Commit downloads the Commit and certifies it with the lite.
 //
 // This is the foundation for all other verification in this module
 func (w Wrapper) Commit(height *int64) (*ctypes.ResultCommit, error) {
+	if height == nil {
+		resStatus, err := w.Client.Status()
+		if err != nil {
+			return nil, err
+		}
+		// NOTE: If resStatus.CatchingUp, there is a race
+		// condition where the validator set for the next height
+		// isn't available until some time after the blockstore
+		// has height h on the remote node.  This isn't an issue
+		// once the node has caught up, and a syncing node likely
+		// won't have this issue esp with the implementation we
+		// have here, but we may have to address this at some
+		// point.
+		height = new(int64)
+		*height = resStatus.SyncInfo.LatestBlockHeight
+	}
 	rpcclient.WaitForHeight(w.Client, *height, nil)
 	res, err := w.Client.Commit(height)
 	// if we got it, then certify it

rpc/core/pipe.go

@@ -3,8 +3,8 @@ package core
 import (
 	"time"
 
-	crypto "github.com/tendermint/tendermint/crypto"
 	"github.com/tendermint/tendermint/consensus"
+	crypto "github.com/tendermint/tendermint/crypto"
 	"github.com/tendermint/tendermint/p2p"
 	"github.com/tendermint/tendermint/proxy"
 	sm "github.com/tendermint/tendermint/state"
@@ -28,6 +28,7 @@ var subscribeTimeout = 5 * time.Second
 type Consensus interface {
 	GetState() sm.State
 	GetValidators() (int64, []*types.Validator)
+	GetLastHeight() int64
 	GetRoundStateJSON() ([]byte, error)
 	GetRoundStateSimpleJSON() ([]byte, error)
 }

rpc/core/status.go

@@ -64,7 +64,12 @@ import (
 //}
 // ```
 func Status() (*ctypes.ResultStatus, error) {
-	latestHeight := blockStore.Height()
+	var latestHeight int64 = -1
+	if consensusReactor.FastSync() {
+		latestHeight = blockStore.Height()
+	} else {
+		latestHeight = consensusState.GetLastHeight()
+	}
 	var (
 		latestBlockMeta     *types.BlockMeta
 		latestBlockHash     cmn.HexBytes