[FAB-3144] Update gossip based on flogging changes

This CR updates gossip-related logging features in light of
the new changes to the `flogging` package. It 1) sets the log
level at peer startup based on the value in core.yaml and 2)
updates the gossip test cases to default to a log level of
`warning`.

Change-Id: I1b254379e8d0d2d0c8521bafcb9ce15ad6420d1a
Signed-off-by: Will Lahti <wtlahti@us.ibm.com>
Signed-off-by: Yacov Manevich <yacovm@il.ibm.com>

gossip/comm/comm_test.go

@@ -44,6 +44,7 @@ import (
 )
 
 func init() {
+	util.SetupTestLogging()
 	rand.Seed(time.Now().UnixNano())
 	factory.InitFactories(nil)
 }

gossip/comm/crypto_test.go

@@ -25,6 +25,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/hyperledger/fabric/gossip/util"
 	proto "github.com/hyperledger/fabric/protos/gossip"
 	"github.com/stretchr/testify/assert"
 	"golang.org/x/net/context"
@@ -40,6 +41,10 @@ type gossipTestServer struct {
 	s              *grpc.Server
 }
 
+func init() {
+	util.SetupTestLogging()
+}
+
 func createTestServer(t *testing.T, cert *tls.Certificate) *gossipTestServer {
 	tlsConf := &tls.Config{
 		Certificates:       []tls.Certificate{*cert},

gossip/discovery/discovery_test.go

@@ -31,6 +31,7 @@ import (
 
 	"github.com/hyperledger/fabric/core/config"
 	"github.com/hyperledger/fabric/gossip/common"
+	"github.com/hyperledger/fabric/gossip/util"
 	proto "github.com/hyperledger/fabric/protos/gossip"
 	"github.com/spf13/viper"
 	"github.com/stretchr/testify/assert"
@@ -42,6 +43,7 @@ import (
 var timeout = time.Second * time.Duration(15)
 
 func init() {
+	util.SetupTestLogging()
 	aliveTimeInterval := time.Duration(time.Millisecond * 100)
 	SetAliveTimeInterval(aliveTimeInterval)
 	SetAliveExpirationTimeout(10 * aliveTimeInterval)

gossip/election/adapter_test.go

@@ -27,9 +27,14 @@ import (
 	"github.com/hyperledger/fabric/gossip/api"
 	"github.com/hyperledger/fabric/gossip/common"
 	"github.com/hyperledger/fabric/gossip/discovery"
+	"github.com/hyperledger/fabric/gossip/util"
 	proto "github.com/hyperledger/fabric/protos/gossip"
 )
 
+func init() {
+	util.SetupTestLogging()
+}
+
 func TestNewAdapter(t *testing.T) {
 	selfNetworkMember := &discovery.NetworkMember{
 		Endpoint: "p0",

gossip/election/election_test.go

@@ -25,6 +25,7 @@ import (
 	"time"
 
 	"github.com/hyperledger/fabric/core/config"
+	"github.com/hyperledger/fabric/gossip/util"
 	"github.com/spf13/viper"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
@@ -36,7 +37,7 @@ const (
 )
 
 func init() {
-
+	util.SetupTestLogging()
 	SetStartupGracePeriod(time.Millisecond * 500)
 	SetMembershipSampleInterval(time.Millisecond * 100)
 	SetLeaderAliveThreshold(time.Millisecond * 500)

gossip/gossip/algo/pull_test.go

@@ -32,6 +32,7 @@ import (
 )
 
 func init() {
+	util.SetupTestLogging()
 	SetDigestWaitTime(time.Duration(100) * time.Millisecond)
 	SetRequestWaitTime(time.Duration(200) * time.Millisecond)
 	SetResponseWaitTime(time.Duration(200) * time.Millisecond)

gossip/gossip/batcher_test.go

@@ -22,9 +22,14 @@ import (
 	"testing"
 	"time"
 
+	"github.com/hyperledger/fabric/gossip/util"
 	"github.com/stretchr/testify/assert"
 )
 
+func init() {
+	util.SetupTestLogging()
+}
+
 func TestBatchingEmitterAddAndSize(t *testing.T) {
 	emitter := newBatchingEmitter(1, 10, time.Second, func(a []interface{}) {})
 	defer emitter.Stop()

gossip/gossip/certstore_test.go

@@ -27,12 +27,14 @@ import (
 	"github.com/hyperledger/fabric/gossip/gossip/algo"
 	"github.com/hyperledger/fabric/gossip/gossip/pull"
 	"github.com/hyperledger/fabric/gossip/identity"
+	"github.com/hyperledger/fabric/gossip/util"
 	proto "github.com/hyperledger/fabric/protos/gossip"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
 )
 
 func init() {
+	util.SetupTestLogging()
 	shortenedWaitTime := time.Millisecond * 300
 	algo.SetDigestWaitTime(shortenedWaitTime / 2)
 	algo.SetRequestWaitTime(shortenedWaitTime)

gossip/gossip/channel/channel_test.go

@@ -31,6 +31,7 @@ import (
 	"github.com/hyperledger/fabric/gossip/common"
 	"github.com/hyperledger/fabric/gossip/discovery"
 	"github.com/hyperledger/fabric/gossip/gossip/algo"
+	"github.com/hyperledger/fabric/gossip/util"
 	proto "github.com/hyperledger/fabric/protos/gossip"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
@@ -50,6 +51,7 @@ var conf = Config{
 }
 
 func init() {
+	util.SetupTestLogging()
 	shortenedWaitTime := time.Millisecond * 300
 	algo.SetDigestWaitTime(shortenedWaitTime / 2)
 	algo.SetRequestWaitTime(shortenedWaitTime)

gossip/gossip/chanstate.go

@@ -26,6 +26,7 @@ import (
 	"github.com/hyperledger/fabric/gossip/common"
 	"github.com/hyperledger/fabric/gossip/discovery"
 	"github.com/hyperledger/fabric/gossip/gossip/channel"
+	"github.com/hyperledger/fabric/gossip/util"
 	proto "github.com/hyperledger/fabric/protos/gossip"
 )
 
@@ -36,6 +37,10 @@ type channelState struct {
 	g        *gossipServiceImpl
 }
 
+func init() {
+	util.SetupTestLogging()
+}
+
 func (cs *channelState) stop() {
 	if cs.isStopping() {
 		return

gossip/gossip/gossip_test.go

@@ -46,6 +46,7 @@ var timeout = time.Second * time.Duration(180)
 var testWG = sync.WaitGroup{}
 
 func init() {
+	util.SetupTestLogging()
 	rand.Seed(int64(time.Now().Second()))
 	aliveTimeInterval := time.Duration(1000) * time.Millisecond
 	discovery.SetAliveTimeInterval(aliveTimeInterval)

gossip/gossip/msgstore/msgs_test.go

@@ -25,10 +25,12 @@ import (
 	"sync"
 
 	"github.com/hyperledger/fabric/gossip/common"
+	"github.com/hyperledger/fabric/gossip/util"
 	"github.com/stretchr/testify/assert"
 )
 
 func init() {
+	util.SetupTestLogging()
 	rand.Seed(time.Now().UnixNano())
 }
 

gossip/gossip/orgs_test.go

@@ -29,11 +29,13 @@ import (
 	"github.com/hyperledger/fabric/gossip/common"
 	"github.com/hyperledger/fabric/gossip/discovery"
 	"github.com/hyperledger/fabric/gossip/identity"
+	"github.com/hyperledger/fabric/gossip/util"
 	proto "github.com/hyperledger/fabric/protos/gossip"
 	"github.com/stretchr/testify/assert"
 )
 
 func init() {
+	util.SetupTestLogging()
 	aliveTimeInterval := time.Duration(1000) * time.Millisecond
 	discovery.SetAliveTimeInterval(aliveTimeInterval)
 	discovery.SetAliveExpirationCheckInterval(aliveTimeInterval)

gossip/gossip/pull/pullstore_test.go

@@ -35,6 +35,7 @@ var pullInterval time.Duration
 var timeoutInterval = 20 * time.Second
 
 func init() {
+	util.SetupTestLogging()
 	pullInterval = time.Duration(500) * time.Millisecond
 	algo.SetDigestWaitTime(pullInterval / 5)
 	algo.SetRequestWaitTime(pullInterval)

gossip/identity/identity_test.go

@@ -24,6 +24,7 @@ import (
 
 	"github.com/hyperledger/fabric/gossip/api"
 	"github.com/hyperledger/fabric/gossip/common"
+	"github.com/hyperledger/fabric/gossip/util"
 	"github.com/stretchr/testify/assert"
 )
 
@@ -33,6 +34,10 @@ type naiveCryptoService struct {
 	revokedIdentities map[string]struct{}
 }
 
+func init() {
+	util.SetupTestLogging()
+}
+
 func (cs *naiveCryptoService) ValidateIdentity(peerIdentity api.PeerIdentityType) error {
 	if _, isRevoked := cs.revokedIdentities[string(cs.GetPKIidOfCert(peerIdentity))]; isRevoked {
 		return errors.New("revoked")

gossip/integration/integration_test.go

@@ -27,12 +27,17 @@ import (
 	"github.com/hyperledger/fabric/gossip/api"
 	"github.com/hyperledger/fabric/gossip/common"
 	"github.com/hyperledger/fabric/gossip/identity"
+	"github.com/hyperledger/fabric/gossip/util"
 	"github.com/hyperledger/fabric/msp/mgmt"
 	"github.com/hyperledger/fabric/msp/mgmt/testtools"
 	"github.com/spf13/viper"
 	"google.golang.org/grpc"
 )
 
+func init() {
+	util.SetupTestLogging()
+}
+
 // This is just a test that shows how to instantiate a gossip component
 func TestNewGossipCryptoService(t *testing.T) {
 	setupTestEnv()

gossip/service/eventer_test.go

@@ -21,13 +21,18 @@ import (
 	"testing"
 
 	"github.com/hyperledger/fabric/common/config"
+	"github.com/hyperledger/fabric/gossip/util"
 	"github.com/hyperledger/fabric/protos/peer"
 )
 
 const testChainID = "foo"
 
 type applicationOrgs []*peer.AnchorPeer
 
+func init() {
+	util.SetupTestLogging()
+}
+
 func (ao applicationOrgs) AnchorPeers() []*peer.AnchorPeer {
 	return ao
 }

gossip/service/gossip_service.go

@@ -122,6 +122,10 @@ var logger = util.GetLogger(util.LoggingServiceModule, "")
 
 // InitGossipService initialize gossip service
 func InitGossipService(peerIdentity []byte, endpoint string, s *grpc.Server, mcs api.MessageCryptoService, bootPeers ...string) {
+	// TODO: Remove this.
+	// TODO: This is a temporary work-around to make the gossip leader election module load its logger at startup
+	// TODO: in order for the flogging package to register this logger in time so it can set the log levels as requested in the config
+	util.GetLogger(util.LoggingElectionModule, "")
 	InitGossipServiceCustomDeliveryFactory(peerIdentity, endpoint, s, &deliveryFactoryImpl{}, mcs, bootPeers...)
 }
 

gossip/service/gossip_service_test.go

@@ -44,6 +44,10 @@ import (
 	"google.golang.org/grpc"
 )
 
+func init() {
+	util.SetupTestLogging()
+}
+
 func TestInitGossipService(t *testing.T) {
 	// Test whenever gossip service is indeed singleton
 	grpcServer := grpc.NewServer()

gossip/service/join_test.go

@@ -25,6 +25,7 @@ import (
 	"github.com/hyperledger/fabric/gossip/comm"
 	"github.com/hyperledger/fabric/gossip/common"
 	"github.com/hyperledger/fabric/gossip/discovery"
+	"github.com/hyperledger/fabric/gossip/util"
 	proto "github.com/hyperledger/fabric/protos/gossip"
 	"github.com/hyperledger/fabric/protos/peer"
 	"github.com/stretchr/testify/assert"
@@ -34,6 +35,10 @@ import (
 type secAdvMock struct {
 }
 
+func init() {
+	util.SetupTestLogging()
+}
+
 func (s *secAdvMock) OrgByPeerIdentity(identity api.PeerIdentityType) api.OrgIdentityType {
 	return api.OrgIdentityType(identity)
 }

gossip/state/metastate_test.go

@@ -20,8 +20,13 @@ import (
 	"testing"
 
 	"github.com/docker/docker/pkg/testutil/assert"
+	"github.com/hyperledger/fabric/gossip/util"
 )
 
+func init() {
+	util.SetupTestLogging()
+}
+
 func TestNewNodeMetastate(t *testing.T) {
 	metastate := NewNodeMetastate(0)
 	assert.Equal(t, metastate.Height(), uint64(0))

gossip/state/payloads_buffer_test.go

@@ -24,10 +24,15 @@ import (
 	"testing"
 	"time"
 
+	"github.com/hyperledger/fabric/gossip/util"
 	proto "github.com/hyperledger/fabric/protos/gossip"
 	"github.com/stretchr/testify/assert"
 )
 
+func init() {
+	util.SetupTestLogging()
+}
+
 func uuid() (string, error) {
 	uuid := make([]byte, 16)
 	_, err := rand.Read(uuid)

gossip/state/state_test.go

@@ -36,6 +36,7 @@ import (
 	"github.com/hyperledger/fabric/gossip/common"
 	"github.com/hyperledger/fabric/gossip/gossip"
 	"github.com/hyperledger/fabric/gossip/identity"
+	gutil "github.com/hyperledger/fabric/gossip/util"
 	pcomm "github.com/hyperledger/fabric/protos/common"
 	proto "github.com/hyperledger/fabric/protos/gossip"
 	"github.com/spf13/viper"
@@ -57,6 +58,10 @@ var noopPeerIdentityAcceptor = func(identity api.PeerIdentityType) error {
 type joinChanMsg struct {
 }
 
+func init() {
+	gutil.SetupTestLogging()
+}
+
 // SequenceNumber returns the sequence number of the block that the message
 // is derived from
 func (*joinChanMsg) SequenceNumber() uint64 {

gossip/util/logging.go

@@ -41,7 +41,9 @@ const (
 
 var loggersByModules = make(map[string]*logging.Logger)
 var lock = sync.Mutex{}
-var logger = flogging.MustGetLogger("gossip/util")
+
+// defaultTestSpec is the default logging level for gossip tests
+var defaultTestSpec = "WARNING"
 
 func init() {
 	grpclog.SetLogger(log.New(ioutil.Discard, "", 0))
@@ -65,3 +67,8 @@ func GetLogger(module string, peerID string) *logging.Logger {
 	loggersByModules[module] = lgr
 	return lgr
 }
+
+// SetupTestLogging sets the default log levels for gossip unit tests
+func SetupTestLogging() {
+	flogging.InitFromSpec(defaultTestSpec)
+}

gossip/util/msgs_test.go

@@ -24,6 +24,10 @@ import (
 	"github.com/stretchr/testify/assert"
 )
 
+func init() {
+	SetupTestLogging()
+}
+
 func TestMembershipStore(t *testing.T) {
 	membershipStore := NewMembershipStore()
 

peer/node/start.go

@@ -264,19 +264,13 @@ func serve(args []string) error {
 	logger.Infof("Started peer with ID=[%s], network ID=[%s], address=[%s]",
 		peerEndpoint.Id, viper.GetString("peer.networkId"), peerEndpoint.Address)
 
-	// if CORE_LOGGING_LEVEL environment variable is not set, set the logging
-	// level for specific modules defined in core.yaml.
-	// TODO Add calls to set 'gossip' and 'ledger' once all other packages
-	// switch to `flogging.MustGetLogger` (from `logging.MustGetLogger`) as those
-	// modules need the regular expression capabilities enabled by the `flogging`
-	// package
-	if viper.GetString("logging_level") == "" {
-		overrideLogModules := []string{"msp"}
-		for _, module := range overrideLogModules {
-			err = common.SetLogLevelFromViper(module)
-			if err != nil {
-				logger.Warningf("Error setting log level for module '%s': %s", module, err.Error())
-			}
+	// set the logging level for specific modules defined in core.yaml.
+	// TODO Add calls to set 'ledger' module loggers
+	overrideLogModules := []string{"msp", "gossip"}
+	for _, module := range overrideLogModules {
+		err = common.SetLogLevelFromViper(module)
+		if err != nil {
+			logger.Warningf("Error setting log level for module '%s': %s", module, err.Error())
 		}
 	}