[FAB-7816] Fix cc event handling and debug

Chaincode event handling was intended to pick up LSCC
chaincode updates, but was also picking up LSCC
chaincode collection updates.

This change ignores chaincode collection updates.

Additionally, related chaincode event debug is improved.

Note that two copies of Collecion-specific constants
were found.  The unused duplicate is removed from lscc.

Change-Id: I8d7c4320d757a7d3327bd2bb22bba0b653febc23
Signed-off-by: David Enyeart <enyeart@us.ibm.com>

Author: denyeart

core/common/privdata/collection.go

@@ -7,6 +7,8 @@ SPDX-License-Identifier: Apache-2.0
 package privdata
 
 import (
+	"strings"
+
 	"github.com/hyperledger/fabric/protos/common"
 )
 
@@ -77,7 +79,7 @@ type CollectionStore interface {
 const (
 	// Collecion-specific constants
 
-	// collectionSeparator is the separator used to build the KVS
+	// CollectionSeparator is the separator used to build the KVS
 	// key storing the collections of a chaincode; note that we are
 	// using as separator a character which is illegal for either the
 	// name or the version of a chaincode so there cannot be any
@@ -92,3 +94,8 @@ const (
 func BuildCollectionKVSKey(ccname string) string {
 	return ccname + collectionSeparator + collectionSuffix
 }
+
+// IsCollectionConfigKey detects if a key is a collection key
+func IsCollectionConfigKey(key string) bool {
+	return strings.Contains(key, collectionSeparator)
+}

core/common/privdata/collection_test.go

@@ -0,0 +1,28 @@
+/*
+Copyright IBM Corp. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package privdata
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestBuildCollectionKVSKey(t *testing.T) {
+
+	chaincodeCollectionKey := BuildCollectionKVSKey("chaincodeKey")
+	assert.Equal(t, "chaincodeKey~collection", chaincodeCollectionKey, "collection keys should end in ~collection")
+}
+
+func TestIsCollectionConfigKey(t *testing.T) {
+
+	isCollection := IsCollectionConfigKey("chaincodeKey")
+	assert.False(t, isCollection, "key without tilda is not a collection key and should have returned false")
+
+	isCollection = IsCollectionConfigKey("chaincodeKey~collection")
+	assert.True(t, isCollection, "key with tilda is a collection key and should have returned true")
+}

core/ledger/cceventmgmt/lsccstate_listener.go

@@ -11,6 +11,7 @@ import (
 
 	"github.com/golang/protobuf/proto"
 	"github.com/hyperledger/fabric/core/common/ccprovider"
+	"github.com/hyperledger/fabric/core/common/privdata"
 	"github.com/hyperledger/fabric/core/ledger"
 	"github.com/hyperledger/fabric/protos/ledger/rwset/kvrwset"
 )
@@ -24,12 +25,21 @@ type KVLedgerLSCCStateListener struct {
 // artifacts for the chaincode statedata)
 func (listener *KVLedgerLSCCStateListener) HandleStateUpdates(channelName string, stateUpdates ledger.StateUpdates) error {
 	kvWrites := stateUpdates.([]*kvrwset.KVWrite)
-	logger.Debugf("HandleStateUpdates() - channelName=%s, stateUpdates=%#v", channelName, kvWrites)
+	logger.Debugf("Channel [%s]: Handling state updates in LSCC namespace - stateUpdates=%#v", channelName, kvWrites)
 	chaincodeDefs := []*ChaincodeDefinition{}
 	for _, kvWrite := range kvWrites {
+		// There are LSCC entries for the chaincode and for the chaincode collections.
+		// We need to ignore changes to chaincode collections, and handle changes to chaincode
+		// We can detect collections based on the presence of a CollectionSeparator, which never exists in chaincode names
+		if privdata.IsCollectionConfigKey(kvWrite.Key) {
+			continue
+		}
+		// Ignore delete events
 		if kvWrite.IsDelete {
 			continue
 		}
+		// Chaincode instantiate/upgrade is not logged on committing peer anywhere else.  This is a good place to log it.
+		logger.Infof("Channel [%s]: Handling LSCC state update for chaincode [%s]", channelName, kvWrite.Key)
 		chaincodeData := &ccprovider.ChaincodeData{}
 		if err := proto.Unmarshal(kvWrite.Value, chaincodeData); err != nil {
 			return fmt.Errorf("Unmarshalling ChaincodeQueryResponse failed, error %s", err)

core/ledger/cceventmgmt/mgmt_test.go

@@ -66,24 +66,57 @@ func TestCCEventMgmt(t *testing.T) {
 
 func TestLSCCListener(t *testing.T) {
 	channelName := "testChannel"
-	cc1Def := &ChaincodeDefinition{Name: "testChaincode", Version: "v1", Hash: []byte("hash_testChaincode")}
-	cc1DBArtifactsTar := []byte("cc1DBArtifacts")
-	// cc1 is installed but not deployed
+
+	cc1Def := &ChaincodeDefinition{Name: "testChaincode1", Version: "v1", Hash: []byte("hash_testChaincode")}
+	cc2Def := &ChaincodeDefinition{Name: "testChaincode2", Version: "v1", Hash: []byte("hash_testChaincode")}
+	cc3Def := &ChaincodeDefinition{Name: "testChaincode~collection", Version: "v1", Hash: []byte("hash_testChaincode")}
+
+	ccDBArtifactsTar := []byte("ccDBArtifacts")
+
+	// cc1, cc2, cc3 installed but not deployed
 	mockProvider := newMockProvider()
-	mockProvider.setChaincodeInstalled(cc1Def, cc1DBArtifactsTar)
+	mockProvider.setChaincodeInstalled(cc1Def, ccDBArtifactsTar)
+	mockProvider.setChaincodeInstalled(cc2Def, ccDBArtifactsTar)
+	mockProvider.setChaincodeInstalled(cc3Def, ccDBArtifactsTar)
+
 	setEventMgrForTest(newMgr(mockProvider))
 	defer clearEventMgrForTest()
 	handler1 := &mockHandler{}
 	GetMgr().Register(channelName, handler1)
 	lsccStateListener := &KVLedgerLSCCStateListener{}
 
-	sampleChaincodeData := &ccprovider.ChaincodeData{Name: cc1Def.Name, Version: cc1Def.Version, Id: cc1Def.Hash}
-	sampleChaincodeDataBytes, err := proto.Marshal(sampleChaincodeData)
-	assert.NoError(t, err, "")
-	lsccStateListener.HandleStateUpdates(channelName, []*kvrwset.KVWrite{
-		{Key: cc1Def.Name, Value: sampleChaincodeDataBytes},
+	// test1 regular deploy lscc event gets sent to handler
+	t.Run("DeployEvent", func(t *testing.T) {
+		sampleChaincodeData1 := &ccprovider.ChaincodeData{Name: cc1Def.Name, Version: cc1Def.Version, Id: cc1Def.Hash}
+		sampleChaincodeDataBytes1, err := proto.Marshal(sampleChaincodeData1)
+		assert.NoError(t, err, "")
+		lsccStateListener.HandleStateUpdates(channelName, []*kvrwset.KVWrite{
+			{Key: cc1Def.Name, Value: sampleChaincodeDataBytes1},
+		})
+		assert.Contains(t, handler1.eventsRecieved, &mockEvent{cc1Def, ccDBArtifactsTar})
+	})
+
+	// test2 delete lscc event NOT sent to handler
+	t.Run("DeleteEvent", func(t *testing.T) {
+		sampleChaincodeData2 := &ccprovider.ChaincodeData{Name: cc2Def.Name, Version: cc2Def.Version, Id: cc2Def.Hash}
+		sampleChaincodeDataBytes2, err := proto.Marshal(sampleChaincodeData2)
+		assert.NoError(t, err, "")
+		lsccStateListener.HandleStateUpdates(channelName, []*kvrwset.KVWrite{
+			{Key: cc2Def.Name, Value: sampleChaincodeDataBytes2, IsDelete: true},
+		})
+		assert.NotContains(t, handler1.eventsRecieved, &mockEvent{cc2Def, ccDBArtifactsTar})
+	})
+
+	// test3 collection lscc event (with tilda separator in chaincode key) NOT sent to handler
+	t.Run("CollectionEvent", func(t *testing.T) {
+		sampleChaincodeData3 := &ccprovider.ChaincodeData{Name: cc3Def.Name, Version: cc3Def.Version, Id: cc3Def.Hash}
+		sampleChaincodeDataBytes3, err := proto.Marshal(sampleChaincodeData3)
+		assert.NoError(t, err, "")
+		lsccStateListener.HandleStateUpdates(channelName, []*kvrwset.KVWrite{
+			{Key: cc3Def.Name, Value: sampleChaincodeDataBytes3},
+		})
+		assert.NotContains(t, handler1.eventsRecieved, &mockEvent{cc3Def, ccDBArtifactsTar})
 	})
-	assert.Contains(t, handler1.eventsRecieved, &mockEvent{cc1Def, cc1DBArtifactsTar})
 }
 
 type mockProvider struct {

core/ledger/cceventmgmt/mgr.go

@@ -72,7 +72,7 @@ func (m *Mgr) Register(ledgerid string, l ChaincodeLifecycleEventListener) {
 // the deployed chaincode. So, in function `HandleChaincodeInstall`, we explicitly check for chaincode deployed
 // in this stored `chaincodeDefinitions`
 func (m *Mgr) HandleChaincodeDeploy(chainid string, chaincodeDefinitions []*ChaincodeDefinition) error {
-	logger.Debugf("HandleChaincodeDeploy() - chainid=%s, chaincodeDefinition=%s", chainid, chaincodeDefinitions)
+	logger.Debugf("Channel [%s]: Handling chaincode deploy event for chaincode [%s]", chainid, chaincodeDefinitions)
 	// Read lock to allow concurrent deploy on multiple channels but to synchronize concurrent `chaincode insall` operation
 	m.rwlock.RLock()
 	defer m.rwlock.RUnlock()
@@ -84,14 +84,15 @@ func (m *Mgr) HandleChaincodeDeploy(chainid string, chaincodeDefinitions []*Chai
 			return err
 		}
 		if !installed {
-			logger.Infof("Chaincode [%s] is not installed hence not creating statedb indexes", chaincodeDefinition)
+			logger.Infof("Channel [%s]: Chaincode [%s] is not installed hence no need to create chaincode artifacts for endorsement",
+				chainid, chaincodeDefinition)
 			continue
 		}
 		if err := m.invokeHandler(chainid, chaincodeDefinition, dbArtifacts); err != nil {
-			logger.Warningf("Error while invoking a listener for handling chaincode install event: %s", err)
+			logger.Warningf("Channel [%s]: Error while invoking a listener for handling chaincode install event: %s", chainid, err)
 			return err
 		}
-		logger.Infof("Created statedb indexes successfully for Chaincode [%s] on channel [%s]", chaincodeDefinition, chainid)
+		logger.Debugf("Channel [%s]: Handled chaincode deploy event for chaincode [%s]", chainid, chaincodeDefinitions)
 	}
 	return nil
 }
@@ -103,25 +104,26 @@ func (m *Mgr) HandleChaincodeInstall(chaincodeDefinition *ChaincodeDefinition, d
 	m.rwlock.Lock()
 	defer m.rwlock.Unlock()
 	for chainid := range m.ccLifecycleListeners {
-		logger.Infof("Handling chaincode install event for chain = %s", chainid)
+		logger.Debugf("Channel [%s]: Handling chaincode install event for chaincode [%s]", chainid, chaincodeDefinition)
 		var deployed bool
 		var err error
 		deployed = m.isChaincodePresentInLatestDeploys(chainid, chaincodeDefinition)
 		if !deployed {
 			if deployed, err = m.infoProvider.IsChaincodeDeployed(chainid, chaincodeDefinition); err != nil {
-				logger.Warningf("Error while getting the deployment status of chaincode: %s", err)
+				logger.Warningf("Channel [%s]: Error while getting the deployment status of chaincode: %s", chainid, err)
 				return err
 			}
 		}
 		if !deployed {
-			logger.Info("chaincode [%s] is not deployed hence ignoring the install event", chaincodeDefinition)
+			logger.Debugf("Channel [%s]: Chaincode [%s] is not deployed on channel hence not creating chaincode artifacts.",
+				chainid, chaincodeDefinition)
 			continue
 		}
 		if err := m.invokeHandler(chainid, chaincodeDefinition, dbArtifacts); err != nil {
-			logger.Warningf("Error while invoking a listener for handling chaincode install event: %s", err)
+			logger.Warningf("Channel [%s]: Error while invoking a listener for handling chaincode install event: %s", chainid, err)
 			return err
 		}
-		logger.Infof("Created statedb indexes successfully for Chaincode [%s] on channel [%s]", chaincodeDefinition, chainid)
+		logger.Debugf("Channel [%s]: Handled chaincode install event for chaincode [%s]", chainid, chaincodeDefinition)
 	}
 	return nil
 }

core/ledger/util/couchdb/couchdb.go

@@ -296,7 +296,7 @@ func (dbclient *CouchDatabase) CreateDatabaseIfNotExist() (*DBOperationResponse,
 		json.NewDecoder(resp.Body).Decode(&dbResponse)
 
 		if dbResponse.Ok == true {
-			logger.Debugf("Created database %s ", dbclient.DBName)
+			logger.Infof("Created state database %s", dbclient.DBName)
 		}
 
 		logger.Debugf("Exiting CreateDatabaseIfNotExist()")
@@ -1120,6 +1120,8 @@ func (dbclient *CouchDatabase) CreateIndex(indexdefinition string) error {
 	}
 	defer closeResponseBody(resp)
 
+	logger.Infof("Created CouchDB index in state database %s", dbclient.DBName)
+
 	return nil
 
 }

core/scc/lscc/lscc.go

@@ -78,18 +78,6 @@ const (
 
 	allowedCharsChaincodeName = "[A-Za-z0-9_-]+"
 	allowedCharsVersion       = "[A-Za-z0-9_.+-]+"
-
-	// Collecion-specific constants
-
-	// collectionSeparator is the separator used to build the KVS
-	// key storing the collections of a chaincode; note that we are
-	// using as separator a character which is illegal for either the
-	// name or the version of a chaincode so there cannot be any
-	// collisions when chosing the name
-	collectionSeparator = "~"
-	// collectionSuffix is the suffix of the KVS key storing the
-	// collections of a chaincode
-	collectionSuffix = "collection"
 )
 
 // Support contains functions that LSCC requires to execute its tasks
@@ -421,6 +409,8 @@ func (lscc *lifeCycleSysCC) executeInstall(stub shim.ChaincodeStubInterface, ccb
 		return err
 	}
 
+	logger.Infof("Installed Chaincode [%s] Version [%s] to peer", ccpack.GetChaincodeData().Name, ccpack.GetChaincodeData().Version)
+
 	return nil
 }