From 8d85ece150fdddef201da98cf18d812dec7164a0 Mon Sep 17 00:00:00 2001 From: Yuval Zalmenson Date: Thu, 14 Feb 2019 12:00:38 +0200 Subject: [PATCH 1/5] adding events in key places --- log/zap.go | 12 +++++++++++- miner/block_builder.go | 3 ++- 2 files changed, 13 insertions(+), 2 deletions(-) diff --git a/log/zap.go b/log/zap.go index 29a97231c4..24bce19e37 100644 --- a/log/zap.go +++ b/log/zap.go @@ -42,16 +42,26 @@ func String(name, val string) Field { return Field(zap.String(name, val)) } +// ByteString returns a byte string ([]byte) Field +func ByteString(name string, val []byte) Field { + return Field(zap.ByteString(name, val)) +} + // Int returns an int Field func Int(name string, val int) Field { return Field(zap.Int(name, val)) } -// Int32 returns an int Field +// Uint32 returns an uint32 Field func Uint32(name string, val uint32) Field { return Field(zap.Uint32(name, val)) } +// Uint64 returns an uint64 Field +func Uint64(name string, val uint64) Field { + return Field(zap.Uint64(name, val)) +} + // Namespace make next fields be inside a namespace. func Namespace(name string) Field { return Field(zap.Namespace(name)) diff --git a/miner/block_builder.go b/miner/block_builder.go index 1c0680fe0c..08f557509d 100644 --- a/miner/block_builder.go +++ b/miner/block_builder.go @@ -154,8 +154,9 @@ func (t *BlockBuilder) listenForTx() { case <-t.stopChan: return case data := <-t.txGossipChannel: - t.Log.Info("got new tx") x, err := mesh.BytesAsTransaction(bytes.NewReader(data.Bytes())) + t.Log.With().Info("got new tx", log.ByteString("sender", x.Origin.Bytes()), log.ByteString("receiver", x.Recipient.Bytes()), + log.ByteString("amount", x.Amount), log.Uint64("nonce", x.AccountNonce), log.Bool("valid", err != nil) ) if err != nil { t.Log.Error("cannot parse incoming TX") data.ReportValidation(IncomingTxProtocol, false) From 365f97ecff8f545964e7dba9ec8bb359724e5de2 Mon Sep 17 00:00:00 2001 From: anton Date: Thu, 14 Feb 2019 14:10:43 +0200 Subject: [PATCH 2/5] added more json logs in state, block receiver and mesh builder --- mesh/block.go | 12 ++++++++++++ mesh/mesh.go | 1 + miner/block_builder.go | 4 ++-- state/processor.go | 9 +++++++-- sync/block_listener.go | 2 +- 5 files changed, 23 insertions(+), 5 deletions(-) diff --git a/mesh/block.go b/mesh/block.go index 4884524446..9c8ddcccca 100644 --- a/mesh/block.go +++ b/mesh/block.go @@ -36,6 +36,18 @@ type SerializableTransaction struct { Payload []byte } +func (t *SerializableTransaction) GetAmount() *big.Int{ + a := &big.Int{} + a.SetBytes(t.Amount) + return a +} + +func (t *SerializableTransaction) GetPrice() *big.Int{ + a := &big.Int{} + a.SetBytes(t.Price) + return a +} + func NewBlock(coin bool, data []byte, ts time.Time, layerId LayerID) *Block { b := Block{ Id: BlockID(uuid.New().ID()), diff --git a/mesh/mesh.go b/mesh/mesh.go index 59bc4d1895..a57c774ff2 100644 --- a/mesh/mesh.go +++ b/mesh/mesh.go @@ -119,6 +119,7 @@ func (m *Mesh) AddLayer(layer *Layer) error { } atomic.StoreUint32(&m.lastSeenLayer, uint32(layer.Index())) m.addLayer(layer) + m.Log.With().Info("added layer", log.Uint32("id", uint32(layer.Index())), log.Int("num of blocks", len(layer.blocks))) m.SetLatestLayer(uint32(layer.Index())) return nil } diff --git a/miner/block_builder.go b/miner/block_builder.go index 08f557509d..c93f40b7cd 100644 --- a/miner/block_builder.go +++ b/miner/block_builder.go @@ -155,8 +155,8 @@ func (t *BlockBuilder) listenForTx() { return case data := <-t.txGossipChannel: x, err := mesh.BytesAsTransaction(bytes.NewReader(data.Bytes())) - t.Log.With().Info("got new tx", log.ByteString("sender", x.Origin.Bytes()), log.ByteString("receiver", x.Recipient.Bytes()), - log.ByteString("amount", x.Amount), log.Uint64("nonce", x.AccountNonce), log.Bool("valid", err != nil) ) + t.Log.With().Info("got new tx", log.String("sender", x.Origin.String()), log.String("receiver", x.Recipient.String()), + log.String("amount", x.GetAmount().String()), log.Uint64("nonce", x.AccountNonce), log.Bool("valid", err != nil) ) if err != nil { t.Log.Error("cannot parse incoming TX") data.ReportValidation(IncomingTxProtocol, false) diff --git a/state/processor.go b/state/processor.go index 967147acd7..5818b56805 100644 --- a/state/processor.go +++ b/state/processor.go @@ -112,12 +112,15 @@ func (tp *TransactionProcessor) ApplyTransactions(layer LayerID, transactions Tr defer tp.mu.Unlock() failed := tp.Process(tp.randomSort(txs), tp.coalesceTransactionsBySender(txs)) newHash, err := tp.globalState.Commit(false) - tp.Log.Info("new state root for layer %v is %x", layer, newHash) + if err != nil { tp.Log.Error("db write error %v", err) return failed, err } + tp.Log.Info("new state root for layer %v is %x", layer, newHash) + tp.Log.With().Info("new state", log.Uint32("layer id", uint32(layer)), log.String("root hash", newHash.String())) + tp.stateQueue.PushBack(newHash) if tp.stateQueue.Len() > maxPastStates { hash := tp.stateQueue.Remove(tp.stateQueue.Back()) @@ -134,10 +137,12 @@ func (tp *TransactionProcessor) Reset(layer LayerID) { defer tp.mu.Unlock() if state, ok := tp.prevStates[layer]; ok { newState, err := New(state, tp.globalState.db) - tp.Log.Info("reverted, new root %x", newState.IntermediateRoot(false)) + if err != nil { panic("cannot revert- improper state") } + tp.Log.Info("reverted, new root %x", newState.IntermediateRoot(false)) + tp.Log.With().Info("reverted", log.String("root hash", newState.IntermediateRoot(false).String())) tp.globalState = newState tp.pruneAfterRevert(layer) diff --git a/sync/block_listener.go b/sync/block_listener.go index b86015f3ed..78670b2beb 100644 --- a/sync/block_listener.go +++ b/sync/block_listener.go @@ -86,7 +86,7 @@ func (bl *BlockListener) ListenToGossipBlocks() { data.ReportValidation(NewBlockProtocol, false) break } - + bl.Log.With().Info("got new block", log.Uint32("id", uint32(blk.Id)), log.Bool("valid", err == nil)) if bl.BlockEligible(blk.LayerIndex, blk.MinerID) { data.ReportValidation(NewBlockProtocol, true) err := bl.AddBlock(&blk) From fb843682c25aa80e0d80e01c7e55c330f34cf583 Mon Sep 17 00:00:00 2001 From: anton Date: Thu, 14 Feb 2019 14:13:39 +0200 Subject: [PATCH 3/5] --amend --- sync/block_listener.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sync/block_listener.go b/sync/block_listener.go index 78670b2beb..b7aec00495 100644 --- a/sync/block_listener.go +++ b/sync/block_listener.go @@ -86,7 +86,7 @@ func (bl *BlockListener) ListenToGossipBlocks() { data.ReportValidation(NewBlockProtocol, false) break } - bl.Log.With().Info("got new block", log.Uint32("id", uint32(blk.Id)), log.Bool("valid", err == nil)) + bl.Log.With().Info("got new block", log.Uint32("id", uint32(blk.Id)), log.Int("txs", len(blk.Txs)), log.Bool("valid", err == nil)) if bl.BlockEligible(blk.LayerIndex, blk.MinerID) { data.ReportValidation(NewBlockProtocol, true) err := bl.AddBlock(&blk) From b6cc280b4cb67759d06d89c83e62f7ec3fe408d5 Mon Sep 17 00:00:00 2001 From: anton Date: Thu, 14 Feb 2019 14:20:32 +0200 Subject: [PATCH 4/5] --amend --- mesh/block.go | 4 ++-- miner/block_builder.go | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/mesh/block.go b/mesh/block.go index 9c8ddcccca..4410088d39 100644 --- a/mesh/block.go +++ b/mesh/block.go @@ -36,13 +36,13 @@ type SerializableTransaction struct { Payload []byte } -func (t *SerializableTransaction) GetAmount() *big.Int{ +func (t *SerializableTransaction) GetAmount() *big.Int { a := &big.Int{} a.SetBytes(t.Amount) return a } -func (t *SerializableTransaction) GetPrice() *big.Int{ +func (t *SerializableTransaction) GetPrice() *big.Int { a := &big.Int{} a.SetBytes(t.Price) return a diff --git a/miner/block_builder.go b/miner/block_builder.go index c93f40b7cd..7485510991 100644 --- a/miner/block_builder.go +++ b/miner/block_builder.go @@ -156,7 +156,7 @@ func (t *BlockBuilder) listenForTx() { case data := <-t.txGossipChannel: x, err := mesh.BytesAsTransaction(bytes.NewReader(data.Bytes())) t.Log.With().Info("got new tx", log.String("sender", x.Origin.String()), log.String("receiver", x.Recipient.String()), - log.String("amount", x.GetAmount().String()), log.Uint64("nonce", x.AccountNonce), log.Bool("valid", err != nil) ) + log.String("amount", x.GetAmount().String()), log.Uint64("nonce", x.AccountNonce), log.Bool("valid", err != nil)) if err != nil { t.Log.Error("cannot parse incoming TX") data.ReportValidation(IncomingTxProtocol, false) From e1c941940529979377d875d30e253bbcdd8d8ecf Mon Sep 17 00:00:00 2001 From: anton Date: Thu, 14 Feb 2019 17:26:11 +0200 Subject: [PATCH 5/5] after CR --- mesh/block.go | 4 ++-- miner/block_builder.go | 2 +- state/processor.go | 4 ++-- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/mesh/block.go b/mesh/block.go index 4410088d39..a4dfedc202 100644 --- a/mesh/block.go +++ b/mesh/block.go @@ -36,13 +36,13 @@ type SerializableTransaction struct { Payload []byte } -func (t *SerializableTransaction) GetAmount() *big.Int { +func (t *SerializableTransaction) AmountAsBigInt() *big.Int { a := &big.Int{} a.SetBytes(t.Amount) return a } -func (t *SerializableTransaction) GetPrice() *big.Int { +func (t *SerializableTransaction) PriceAsBigInt() *big.Int { a := &big.Int{} a.SetBytes(t.Price) return a diff --git a/miner/block_builder.go b/miner/block_builder.go index 7485510991..d1b0e52348 100644 --- a/miner/block_builder.go +++ b/miner/block_builder.go @@ -156,7 +156,7 @@ func (t *BlockBuilder) listenForTx() { case data := <-t.txGossipChannel: x, err := mesh.BytesAsTransaction(bytes.NewReader(data.Bytes())) t.Log.With().Info("got new tx", log.String("sender", x.Origin.String()), log.String("receiver", x.Recipient.String()), - log.String("amount", x.GetAmount().String()), log.Uint64("nonce", x.AccountNonce), log.Bool("valid", err != nil)) + log.String("amount", x.AmountAsBigInt().String()), log.Uint64("nonce", x.AccountNonce), log.Bool("valid", err != nil)) if err != nil { t.Log.Error("cannot parse incoming TX") data.ReportValidation(IncomingTxProtocol, false) diff --git a/state/processor.go b/state/processor.go index 5818b56805..bb3adc08f2 100644 --- a/state/processor.go +++ b/state/processor.go @@ -119,7 +119,7 @@ func (tp *TransactionProcessor) ApplyTransactions(layer LayerID, transactions Tr } tp.Log.Info("new state root for layer %v is %x", layer, newHash) - tp.Log.With().Info("new state", log.Uint32("layer id", uint32(layer)), log.String("root hash", newHash.String())) + tp.Log.With().Info("new state", log.Uint32("layer_id", uint32(layer)), log.String("root_hash", newHash.String())) tp.stateQueue.PushBack(newHash) if tp.stateQueue.Len() > maxPastStates { @@ -142,7 +142,7 @@ func (tp *TransactionProcessor) Reset(layer LayerID) { panic("cannot revert- improper state") } tp.Log.Info("reverted, new root %x", newState.IntermediateRoot(false)) - tp.Log.With().Info("reverted", log.String("root hash", newState.IntermediateRoot(false).String())) + tp.Log.With().Info("reverted", log.String("root_hash", newState.IntermediateRoot(false).String())) tp.globalState = newState tp.pruneAfterRevert(layer)