[FAB-4842] Improve logging for invalid txs

See the JIRA for more details, but this change
adds the channel and transaction id to the
warning message for invalid transactions.

Change-Id: Ie07a1c29d03097e366466bf4657d1dae8a3948d8
Signed-off-by: Gari Singh <gari.r.singh@gmail.com>

Author: mastersingh24

core/ledger/kvledger/txmgmt/validator/valimpl/helper.go

@@ -77,7 +77,7 @@ func validatePvtdata(tx *valinternal.Transaction, pvtdata *ledger.TxPvtData) err
 			hashInPubdata := tx.RetrieveHash(nsPvtdata.Namespace, collPvtdata.CollectionName)
 			if !bytes.Equal(collPvtdataHash, hashInPubdata) {
 				return &validator.ErrPvtdataHashMissmatch{
-					Msg: fmt.Sprintf(`Hash of pvt data for collection [%s:%s] does not match with the corresponding hash in the public data. 
+					Msg: fmt.Sprintf(`Hash of pvt data for collection [%s:%s] does not match with the corresponding hash in the public data.
 					public hash = [%#v], pvt data hash = [%#v]`, nsPvtdata.Namespace, collPvtdata.CollectionName, hashInPubdata, collPvtdataHash),
 				}
 			}
@@ -98,24 +98,27 @@ func preprocessProtoBlock(txmgr txmgr.TxMgr, block *common.Block) (*valinternal.
 		block.Metadata.Metadata[common.BlockMetadataIndex_TRANSACTIONS_FILTER] = txsFilter
 	}
 	for txIndex, envBytes := range block.Data.Data {
+		var env *common.Envelope
+		var chdr *common.ChannelHeader
+		var payload *common.Payload
+		var err error
+		if env, err = utils.GetEnvelopeFromBlock(envBytes); err == nil {
+			if payload, err = utils.GetPayload(env); err == nil {
+				chdr, err = utils.UnmarshalChannelHeader(payload.Header.ChannelHeader)
+			}
+		}
 		if txsFilter.IsInvalid(txIndex) {
-			// Skiping invalid transaction
-			logger.Warningf("Block [%d] Transaction index [%d] marked as invalid by committer. Reason code [%d]",
-				block.Header.Number, txIndex, txsFilter.Flag(txIndex))
+			// Skipping invalid transaction
+			logger.Warningf("Channel [%s]: Block [%d] Transaction index [%d] TxId [%s]"+
+				" marked as invalid by committer. Reason code [%s]",
+				chdr.GetChannelId(), block.Header.Number, txIndex, chdr.GetTxId(),
+				txsFilter.Flag(txIndex).String())
 			continue
 		}
-		env, err := utils.GetEnvelopeFromBlock(envBytes)
-		if err != nil {
-			return nil, err
-		}
-		payload, err := utils.GetPayload(env)
-		if err != nil {
-			return nil, err
-		}
-		chdr, err := utils.UnmarshalChannelHeader(payload.Header.ChannelHeader)
 		if err != nil {
 			return nil, err
 		}
+
 		var txRWSet *rwsetutil.TxRwSet
 		txType := common.HeaderType(chdr.Type)
 		logger.Debugf("txType=%s", txType)

core/ledger/kvledger/txmgmt/validator/valimpl/helper_test.go

@@ -0,0 +1,105 @@
+/*
+Copyright IBM Corp. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package valimpl
+
+import (
+	"fmt"
+	"testing"
+
+	"github.com/hyperledger/fabric/common/ledger/testutil"
+	"github.com/hyperledger/fabric/common/util"
+	lutils "github.com/hyperledger/fabric/core/ledger/util"
+	"github.com/hyperledger/fabric/protos/common"
+	"github.com/hyperledger/fabric/protos/peer"
+	putils "github.com/hyperledger/fabric/protos/utils"
+	"github.com/op/go-logging"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestPreprocessProtoBlock(t *testing.T) {
+
+	// good block
+	//_, gb := testutil.NewBlockGenerator(t, "testLedger", false)
+	gb := testutil.ConstructTestBlock(t, 10, 1, 1)
+	_, err := preprocessProtoBlock(nil, gb)
+	assert.NoError(t, err)
+	// bad envelope
+	gb = testutil.ConstructTestBlock(t, 11, 1, 1)
+	gb.Data = &common.BlockData{Data: [][]byte{[]byte{123}}}
+	gb.Metadata.Metadata[common.BlockMetadataIndex_TRANSACTIONS_FILTER] =
+		lutils.NewTxValidationFlags(len(gb.Data.Data))
+	_, err = preprocessProtoBlock(nil, gb)
+	assert.Error(t, err)
+	t.Log(err)
+	// bad payload
+	gb = testutil.ConstructTestBlock(t, 12, 1, 1)
+	envBytes, _ := putils.GetBytesEnvelope(&common.Envelope{Payload: []byte{123}})
+	gb.Data = &common.BlockData{Data: [][]byte{envBytes}}
+	_, err = preprocessProtoBlock(nil, gb)
+	assert.Error(t, err)
+	t.Log(err)
+	// bad channel header
+	gb = testutil.ConstructTestBlock(t, 13, 1, 1)
+	payloadBytes, _ := putils.GetBytesPayload(&common.Payload{
+		Header: &common.Header{ChannelHeader: []byte{123}},
+	})
+	envBytes, _ = putils.GetBytesEnvelope(&common.Envelope{Payload: payloadBytes})
+	gb.Data = &common.BlockData{Data: [][]byte{envBytes}}
+	_, err = preprocessProtoBlock(nil, gb)
+	assert.Error(t, err)
+	t.Log(err)
+
+	// bad channel header with invalid filter set
+	gb = testutil.ConstructTestBlock(t, 14, 1, 1)
+	payloadBytes, _ = putils.GetBytesPayload(&common.Payload{
+		Header: &common.Header{ChannelHeader: []byte{123}},
+	})
+	envBytes, _ = putils.GetBytesEnvelope(&common.Envelope{Payload: payloadBytes})
+	gb.Data = &common.BlockData{Data: [][]byte{envBytes}}
+	flags := lutils.NewTxValidationFlags(len(gb.Data.Data))
+	flags.SetFlag(0, peer.TxValidationCode_BAD_CHANNEL_HEADER)
+	gb.Metadata.Metadata[common.BlockMetadataIndex_TRANSACTIONS_FILTER] = flags
+	_, err = preprocessProtoBlock(nil, gb)
+	assert.NoError(t, err) // invalid filter should take precendence
+
+	// new block
+	var blockNum uint64 = 15
+	txid := "testtxid1234"
+	gb = testutil.ConstructBlockWithTxid(t, blockNum, []byte{123},
+		[][]byte{[]byte{123}}, []string{txid}, false)
+	flags = lutils.NewTxValidationFlags(len(gb.Data.Data))
+	flags.SetFlag(0, peer.TxValidationCode_BAD_HEADER_EXTENSION)
+	gb.Metadata.Metadata[common.BlockMetadataIndex_TRANSACTIONS_FILTER] = flags
+	// set logging backend for test
+	backend := logging.NewMemoryBackend(1)
+	logging.SetBackend(backend)
+	_, err = preprocessProtoBlock(nil, gb)
+	assert.NoError(t, err)
+	expected := fmt.Sprintf("Channel [%s]: Block [%d] Transaction index [%d] TxId [%s]"+
+		" marked as invalid by committer. Reason code [%s]",
+		util.GetTestChainID(), blockNum, 0, txid, peer.TxValidationCode_BAD_HEADER_EXTENSION.String())
+	t.Log(expected)
+	assert.Equal(t, expected, memoryRecordN(backend, 0).Message())
+	//assert.Equal(t, message, MemoryRecordN(backend, i).Message())
+	t.Log(memoryRecordN(backend, 0).Message())
+
+}
+
+// from go-logging memory_test.go
+func memoryRecordN(b *logging.MemoryBackend, n int) *logging.Record {
+	node := b.Head()
+	for i := 0; i < n; i++ {
+		if node == nil {
+			break
+		}
+		node = node.Next()
+	}
+	if node == nil {
+		return nil
+	}
+	return node.Record
+}