Commit 0ea65fd1 authored by Christopher Ferris's avatar Christopher Ferris
Browse files

Aligned logging in membersrvc with that in peer.

Moved logging modules from core to its own package so it could be shared, renamed flogging.
Fixes #897 https://github.com/hyperledger/fabric/issues/897
patch set from https://github.com/hyperledger/fabric/pull/2300


address review comment
rebased

Change-Id: I1124bf8f771dbf4d34cc836437caa1d5526f4f43
Signed-off-by: default avatarChristopher Ferris <chrisfer@us.ibm.com>
parent dc6e24a3
......@@ -18,7 +18,6 @@ package chaincode
import (
"fmt"
"io/ioutil"
"net"
"os"
"strconv"
......@@ -56,7 +55,6 @@ func initMemSrvc() (net.Listener, error) {
//start clean
finitMemSrvc(nil)
ca.LogInit(ioutil.Discard, os.Stdout, os.Stdout, os.Stderr, os.Stdout)
ca.CacheConfiguration() // Cache configuration
aca := ca.NewACA()
......
......@@ -22,7 +22,6 @@ import (
"bytes"
"fmt"
"io/ioutil"
"net"
"os"
"path/filepath"
......@@ -436,7 +435,7 @@ func TestClientGetNextTCerts(t *testing.T) {
var nCerts int = 1
for i := 1; i < 3; i++ {
nCerts *= 10
fmt.Println(fmt.Sprintf("Calling GetNextTCerts(%d)", nCerts))
t.Logf("Calling GetNextTCerts(%d)", nCerts)
rvCerts, err := deployer.GetNextTCerts(nCerts)
if err != nil {
t.Fatalf("Could not receive %d TCerts", nCerts)
......@@ -1524,7 +1523,6 @@ func setup() {
}
func initPKI() {
ca.LogInit(ioutil.Discard, os.Stdout, os.Stdout, os.Stderr, os.Stdout)
ca.CacheConfiguration() // Need cache the configuration first
aca = ca.NewACA()
eca = ca.NewECA()
......@@ -1567,21 +1565,18 @@ func initNodes() {
// Init clients
err := initClients()
if err != nil {
fmt.Printf("Failed initializing clients [%s]\n", err)
panic(fmt.Errorf("Failed initializing clients [%s].", err))
}
// Init peer
err = initPeers()
if err != nil {
fmt.Printf("Failed initializing peers [%s]\n", err)
panic(fmt.Errorf("Failed initializing peers [%s].", err))
}
// Init validators
err = initValidators()
if err != nil {
fmt.Printf("Failed initializing validators [%s]\n", err)
panic(fmt.Errorf("Failed initializing validators [%s].", err))
}
......
......@@ -14,7 +14,7 @@ See the License for the specific language governing permissions and
limitations under the License.
*/
package core
package flogging
import (
"os"
......
......@@ -14,11 +14,12 @@ See the License for the specific language governing permissions and
limitations under the License.
*/
package core
package flogging_test
import (
"testing"
"github.com/hyperledger/fabric/flogging"
"github.com/op/go-logging"
"github.com/spf13/viper"
)
......@@ -26,16 +27,16 @@ import (
func TestLoggingLevelDefault(t *testing.T) {
viper.Reset()
LoggingInit("")
flogging.LoggingInit("")
assertDefaultLoggingLevel(t, DefaultLoggingLevel())
assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel())
}
func TestLoggingLevelOtherThanDefault(t *testing.T) {
viper.Reset()
viper.Set("logging_level", "warning")
LoggingInit("")
flogging.LoggingInit("")
assertDefaultLoggingLevel(t, logging.WARNING)
}
......@@ -44,7 +45,7 @@ func TestLoggingLevelForSpecificModule(t *testing.T) {
viper.Reset()
viper.Set("logging_level", "core=info")
LoggingInit("")
flogging.LoggingInit("")
assertModuleLoggingLevel(t, "core", logging.INFO)
}
......@@ -53,7 +54,7 @@ func TestLoggingLeveltForMultipleModules(t *testing.T) {
viper.Reset()
viper.Set("logging_level", "core=warning:test=debug")
LoggingInit("")
flogging.LoggingInit("")
assertModuleLoggingLevel(t, "core", logging.WARNING)
assertModuleLoggingLevel(t, "test", logging.DEBUG)
......@@ -63,7 +64,7 @@ func TestLoggingLevelForMultipleModulesAtSameLevel(t *testing.T) {
viper.Reset()
viper.Set("logging_level", "core,test=warning")
LoggingInit("")
flogging.LoggingInit("")
assertModuleLoggingLevel(t, "core", logging.WARNING)
assertModuleLoggingLevel(t, "test", logging.WARNING)
......@@ -73,7 +74,7 @@ func TestLoggingLevelForModuleWithDefault(t *testing.T) {
viper.Reset()
viper.Set("logging_level", "info:test=warning")
LoggingInit("")
flogging.LoggingInit("")
assertDefaultLoggingLevel(t, logging.INFO)
assertModuleLoggingLevel(t, "test", logging.WARNING)
......@@ -83,7 +84,7 @@ func TestLoggingLevelForModuleWithDefaultAtEnd(t *testing.T) {
viper.Reset()
viper.Set("logging_level", "test=warning:info")
LoggingInit("")
flogging.LoggingInit("")
assertDefaultLoggingLevel(t, logging.INFO)
assertModuleLoggingLevel(t, "test", logging.WARNING)
......@@ -93,7 +94,7 @@ func TestLoggingLevelForSpecificCommand(t *testing.T) {
viper.Reset()
viper.Set("logging.node", "error")
LoggingInit("node")
flogging.LoggingInit("node")
assertDefaultLoggingLevel(t, logging.ERROR)
}
......@@ -101,45 +102,45 @@ func TestLoggingLevelForSpecificCommand(t *testing.T) {
func TestLoggingLevelForUnknownCommandGoesToDefault(t *testing.T) {
viper.Reset()
LoggingInit("unknown command")
flogging.LoggingInit("unknown command")
assertDefaultLoggingLevel(t, DefaultLoggingLevel())
assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel())
}
func TestLoggingLevelInvalid(t *testing.T) {
viper.Reset()
viper.Set("logging_level", "invalidlevel")
LoggingInit("")
flogging.LoggingInit("")
assertDefaultLoggingLevel(t, DefaultLoggingLevel())
assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel())
}
func TestLoggingLevelInvalidModules(t *testing.T) {
viper.Reset()
viper.Set("logging_level", "core=invalid")
LoggingInit("")
flogging.LoggingInit("")
assertDefaultLoggingLevel(t, DefaultLoggingLevel())
assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel())
}
func TestLoggingLevelInvalidEmptyModule(t *testing.T) {
viper.Reset()
viper.Set("logging_level", "=warning")
LoggingInit("")
flogging.LoggingInit("")
assertDefaultLoggingLevel(t, DefaultLoggingLevel())
assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel())
}
func TestLoggingLevelInvalidModuleSyntax(t *testing.T) {
viper.Reset()
viper.Set("logging_level", "type=warn=again")
LoggingInit("")
flogging.LoggingInit("")
assertDefaultLoggingLevel(t, DefaultLoggingLevel())
assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel())
}
func assertDefaultLoggingLevel(t *testing.T, expectedLevel logging.Level) {
......
......@@ -19,7 +19,6 @@ package ca
import (
"encoding/asn1"
"errors"
"fmt"
"google/protobuf"
"strings"
"time"
......@@ -28,12 +27,16 @@ import (
"database/sql"
"github.com/hyperledger/fabric/flogging"
"github.com/op/go-logging"
"github.com/spf13/viper"
"google.golang.org/grpc"
pb "github.com/hyperledger/fabric/membersrvc/protos"
)
var acaLogger = logging.MustGetLogger("aca")
var (
//ACAAttribute is the base OID to the attributes extensions.
ACAAttribute = asn1.ObjectIdentifier{1, 2, 3, 4, 5, 6, 10}
......@@ -220,7 +223,7 @@ func (attrPair *AttributePair) ToACAAttribute() *pb.ACAAttribute {
// NewACA sets up a new ACA.
func NewACA() *ACA {
aca := &ACA{CA: NewCA("aca", initializeACATables)}
flogging.LoggingInit("aca")
return aca
}
......@@ -263,12 +266,12 @@ func (aca *ACA) fetchAttributes(id, affiliation string) ([]*AttributePair, error
}
attributes = append(attributes, attrPair)
} else {
Error.Printf("Invalid attribute entry '%v'", vals[0])
acaLogger.Errorf("Invalid attribute entry '%v'", vals[0])
}
}
}
fmt.Printf("%v %v", id, attributes)
acaLogger.Debugf("%v %v", id, attributes)
return attributes, nil
}
......@@ -365,28 +368,28 @@ func (aca *ACA) findAttribute(owner *AttributeOwner, attributeName string) (*Att
func (aca *ACA) startACAP(srv *grpc.Server) {
pb.RegisterACAPServer(srv, &ACAP{aca})
Info.Println("ACA PUBLIC gRPC API server started")
acaLogger.Info("ACA PUBLIC gRPC API server started")
}
// Start starts the ACA.
func (aca *ACA) Start(srv *grpc.Server) {
Info.Println("Staring ACA services...")
acaLogger.Info("Staring ACA services...")
aca.startACAP(srv)
aca.gRPCServer = srv
Info.Println("ACA services started")
acaLogger.Info("ACA services started")
}
// Stop stops the ACA
func (aca *ACA) Stop() error {
Info.Println("Stopping the ACA services...")
acaLogger.Info("Stopping the ACA services...")
if aca.gRPCServer != nil {
aca.gRPCServer.Stop()
}
err := aca.CA.Stop()
if err != nil {
Error.Println("Error stopping the ACA services ", err)
acaLogger.Errorf("Error stopping the ACA services: %s ", err)
} else {
Info.Println("ACA services stopped")
acaLogger.Info("ACA services stopped")
}
return err
}
......@@ -26,12 +26,15 @@ import (
"crypto/x509/pkix"
"github.com/golang/protobuf/proto"
"github.com/op/go-logging"
"golang.org/x/net/context"
"github.com/hyperledger/fabric/core/crypto/primitives"
pb "github.com/hyperledger/fabric/membersrvc/protos"
)
var acapLogger = logging.MustGetLogger("acap")
// ACAP serves the public GRPC interface of the ACA.
//
type ACAP struct {
......@@ -40,7 +43,7 @@ type ACAP struct {
// FetchAttributes fetchs the attributes from the outside world and populate them into the database.
func (acap *ACAP) FetchAttributes(ctx context.Context, in *pb.ACAFetchAttrReq) (*pb.ACAFetchAttrResp, error) {
Trace.Println("grpc ACAP:FetchAttributes")
acapLogger.Debug("grpc ACAP:FetchAttributes")
if in.Ts == nil || in.ECert == nil || in.Signature == nil {
return &pb.ACAFetchAttrResp{Status: pb.ACAFetchAttrResp_FAILURE, Msg: "Bad request"}, nil
......@@ -107,7 +110,7 @@ func (acap *ACAP) createRequestAttributeResponse(status pb.ACAAttrResp_StatusCod
// RequestAttributes lookups the atributes in the database and return a certificate with attributes included in the request and found in the database.
func (acap *ACAP) RequestAttributes(ctx context.Context, in *pb.ACAAttrReq) (*pb.ACAAttrResp, error) {
Trace.Println("grpc ACAP:RequestAttributes")
acapLogger.Debug("grpc ACAP:RequestAttributes")
fail := pb.ACAAttrResp_FULL_SUCCESSFUL // else explicit which-param-failed error
if nil == in.Ts {
......@@ -225,7 +228,7 @@ func (acap *ACAP) addAttributesToExtensions(attributes *[]AttributePair, extensi
// ReadCACertificate reads the certificate of the ACA.
//
func (acap *ACAP) ReadCACertificate(ctx context.Context, in *pb.Empty) (*pb.Cert, error) {
Trace.Println("grpc ACAP:ReadCACertificate")
acapLogger.Debug("grpc ACAP:ReadCACertificate")
return &pb.Cert{Cert: acap.aca.raw}, nil
}
......@@ -36,12 +36,15 @@ import (
"time"
"github.com/hyperledger/fabric/core/crypto/primitives"
"github.com/hyperledger/fabric/flogging"
pb "github.com/hyperledger/fabric/membersrvc/protos"
_ "github.com/mattn/go-sqlite3" // This blank import is required to load sqlite3 driver
"github.com/op/go-logging"
"github.com/spf13/viper"
)
var caLogger = logging.MustGetLogger("ca")
// CA is the base certificate authority.
type CA struct {
db *sql.DB
......@@ -123,6 +126,7 @@ func NewDefaultCertificateSpecWithCommonName(id string, commonName string, pub i
return NewDefaultPeriodCertificateSpecWithCommonName(id, commonName, serialNumber, pub, usage, opt...)
}
// CacheConfiguration caches the viper configuration
func CacheConfiguration() {
caOrganization = viper.GetString("pki.ca.subject.organization")
caCountry = viper.GetString("pki.ca.subject.country")
......@@ -221,28 +225,29 @@ func initializeCommonTables(db *sql.DB) error {
// NewCA sets up a new CA.
func NewCA(name string, initTables TableInitializer) *CA {
ca := new(CA)
flogging.LoggingInit("ca")
ca.path = filepath.Join(rootPath, caDir)
if _, err := os.Stat(ca.path); err != nil {
Info.Println("Fresh start; creating databases, key pairs, and certificates.")
caLogger.Info("Fresh start; creating databases, key pairs, and certificates.")
if err := os.MkdirAll(ca.path, 0755); err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
}
// open or create certificate database
db, err := sql.Open("sqlite3", ca.path+"/"+name+".db")
if err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
if err = db.Ping(); err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
if err = initTables(db); err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
ca.db = db
......@@ -260,7 +265,7 @@ func NewCA(name string, initTables TableInitializer) *CA {
}
cert, err := x509.ParseCertificate(raw)
if err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
ca.raw = raw
......@@ -269,19 +274,19 @@ func NewCA(name string, initTables TableInitializer) *CA {
return ca
}
// Close closes down the CA.
// Stop Close closes down the CA.
func (ca *CA) Stop() error {
err := ca.db.Close()
if err == nil {
Trace.Println("Shutting down CA - Successfully")
caLogger.Debug("Shutting down CA - Successfully")
} else {
Trace.Println(fmt.Sprintf("Shutting down CA - Error closing DB [%s]", err))
caLogger.Debug(fmt.Sprintf("Shutting down CA - Error closing DB [%s]", err))
}
return err
}
func (ca *CA) createCAKeyPair(name string) *ecdsa.PrivateKey {
Trace.Println("Creating CA key pair.")
caLogger.Debug("Creating CA key pair.")
curve := primitives.GetDefaultCurve()
......@@ -295,7 +300,7 @@ func (ca *CA) createCAKeyPair(name string) *ecdsa.PrivateKey {
})
err = ioutil.WriteFile(ca.path+"/"+name+".priv", cooked, 0644)
if err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
raw, _ = x509.MarshalPKIXPublicKey(&priv.PublicKey)
......@@ -306,18 +311,18 @@ func (ca *CA) createCAKeyPair(name string) *ecdsa.PrivateKey {
})
err = ioutil.WriteFile(ca.path+"/"+name+".pub", cooked, 0644)
if err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
}
if err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
return priv
}
func (ca *CA) readCAPrivateKey(name string) (*ecdsa.PrivateKey, error) {
Trace.Println("Reading CA private key.")
caLogger.Debug("Reading CA private key.")
cooked, err := ioutil.ReadFile(ca.path + "/" + name + ".priv")
if err != nil {
......@@ -329,11 +334,11 @@ func (ca *CA) readCAPrivateKey(name string) (*ecdsa.PrivateKey, error) {
}
func (ca *CA) createCACertificate(name string, pub *ecdsa.PublicKey) []byte {
Trace.Println("Creating CA certificate.")
caLogger.Debug("Creating CA certificate.")
raw, err := ca.newCertificate(name, pub, x509.KeyUsageDigitalSignature|x509.KeyUsageCertSign, nil)
if err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
cooked := pem.EncodeToMemory(
......@@ -343,14 +348,14 @@ func (ca *CA) createCACertificate(name string, pub *ecdsa.PublicKey) []byte {
})
err = ioutil.WriteFile(ca.path+"/"+name+".cert", cooked, 0644)
if err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
return raw
}
func (ca *CA) readCACertificate(name string) ([]byte, error) {
Trace.Println("Reading CA certificate.")
caLogger.Debug("Reading CA certificate.")
cooked, err := ioutil.ReadFile(ca.path + "/" + name + ".cert")
if err != nil {
......@@ -367,11 +372,11 @@ func (ca *CA) createCertificate(id string, pub interface{}, usage x509.KeyUsage,
}
func (ca *CA) createCertificateFromSpec(spec *CertificateSpec, timestamp int64, kdfKey []byte, persist bool) ([]byte, error) {
Trace.Println("Creating certificate for " + spec.GetID() + ".")
caLogger.Debug("Creating certificate for " + spec.GetID() + ".")
raw, err := ca.newCertificateFromSpec(spec)
if err != nil {
Error.Println(err)
caLogger.Error(err)
return nil, err
}
......@@ -391,7 +396,7 @@ func (ca *CA) persistCertificate(id string, timestamp int64, usage x509.KeyUsage
var err error
if _, err = ca.db.Exec("INSERT INTO Certificates (id, timestamp, usage, cert, hash, kdfkey) VALUES (?, ?, ?, ?, ?, ?)", id, timestamp, usage, certRaw, hash.Sum(nil), kdfKey); err != nil {
Error.Println(err)
caLogger.Error(err)
}
return err
}
......@@ -442,14 +447,14 @@ func (ca *CA) newCertificateFromSpec(spec *CertificateSpec) ([]byte, error) {
ca.priv,
)
if isCA && err != nil {
Panic.Panicln(err)
caLogger.Panic(err)
}
return raw, err
}
func (ca *CA) readCertificateByKeyUsage(id string, usage x509.KeyUsage) ([]byte, error) {
Trace.Printf("Reading certificate for %s and usage %v", id, usage)
caLogger.Debugf("Reading certificate for %s and usage %v", id, usage)
mutex.RLock()
defer mutex.RUnlock()
......@@ -458,14 +463,14 @@ func (ca *CA) readCertificateByKeyUsage(id string, usage x509.KeyUsage) ([]byte,
err := ca.db.QueryRow("SELECT cert FROM Certificates WHERE id=? AND usage=?", id, usage).Scan(&raw)
if err != nil {
Trace.Printf("readCertificateByKeyUsage() Error: %v", err)
caLogger.Debugf("readCertificateByKeyUsage() Error: %v", err)
}
return raw, err
}
func (ca *CA) readCertificateByTimestamp(id string, ts int64) ([]byte, error) {
Trace.Println("Reading certificate for " + id + ".")
caLogger.Debug("Reading certificate for " + id + ".")
mutex.RLock()
defer mutex.RUnlock()
......@@ -477,7 +482,7 @@ func (ca *CA) readCertificateByTimestamp(id string, ts int64) ([]byte, error) {
}
func (ca *CA) readCertificates(id string, opt ...int64) (*sql.Rows, error) {
Trace.Println("Reading certificatess for " + id + ".")
caLogger.Debug("Reading certificatess for " + id + ".")
mutex.RLock()
defer mutex.RUnlock()
......@@ -490,7 +495,7 @@ func (ca *CA) readCertificates(id string, opt ...int64) (*sql.Rows, error) {
}
func (ca *CA) readCertificateSets(id string, start, end int64) (*sql.Rows, error) {
Trace.Println("Reading certificate sets for " + id + ".")
caLogger.Debug("Reading certificate sets for " + id + ".")
mutex.RLock()
defer mutex.RUnlock()
......@@ -499,7 +504,7 @@ func (ca *CA) readCertificateSets(id string, start, end int64) (*sql.Rows, error
}
func (ca *CA) readCertificateByHash(hash []byte) ([]byte, error) {
Trace.Println("Reading certificate for hash " + string(hash) + ".")
caLogger.Debug("Reading certificate for hash " + string(hash) + ".")
mutex.RLock()
defer mutex.RUnlock()
......@@ -512,7 +517,7 @@ func (ca *CA) readCertificateByHash(hash []byte) ([]byte, error) {
}
func (ca *CA) isValidAffiliation(affiliation string) (bool, error) {
Trace.Println("Validating affiliation: " + affiliation)
caLogger.Debug("Validating affiliation: " + affiliation)
mutex.RLock()
defer mutex.RUnlock()
......@@ -521,11 +526,11 @@ func (ca *CA) isValidAffiliation(affiliation string) (bool, error) {
var err error
err = ca.db.QueryRow("SELECT count(row) FROM AffiliationGroups WHERE name=?", affiliation).Scan(&count)
if err != nil {
Trace.Println("Affiliation <" + affiliation + "> is INVALID.")
caLogger.Debug("Affiliation <" + affiliation + "> is INVALID.")
return false, err
}
Trace.Println("Affiliation <" + affiliation + "> is VALID.")
caLogger.Debug("Affiliation <" + affiliation + "> is VALID.")
return count == 1, nil
}
......@@ -540,7 +545,7 @@ func (ca *CA) isValidAffiliation(affiliation string) (bool, error) {
func (ca *CA) requireAffiliation(role pb.Role) bool {
roleStr, _ := MemberRoleToString(role)
Trace.Println("Assigned role is: " + roleStr + ".")
caLogger.Debug("Assigned role is: " + roleStr + ".")
return role != pb.Role_VALIDATOR && role != pb.Role_AUDITOR
}
......@@ -548,7 +553,7 @@ func (ca *CA) requireAffiliation(role pb.Role) bool {
// validateAndGenerateEnrollID validates the affiliation subject
func (ca *CA) validateAndGenerateEnrollID(id, affiliation string, role pb.Role) (string, error) {
roleStr, _ := MemberRoleToString(role)
Trace.Println("Validating and generating enrollID for user id: " + id + ", affiliation: " + affiliation + ", role: " + roleStr + ".")
caLogger.Debug("Validating and generating enrollID for user id: " + id + ", affiliation: " + affiliation + ", role: " + roleStr + ".")
// Check whether the affiliation is required for the current user.
//
......@@ -561,7 +566,7 @@ func (ca *CA) validateAndGenerateEnrollID(id, affiliation string, role pb.Role)
}
if !valid {
Trace.Println("Invalid affiliation group: ")
caLogger.Debug("Invalid affiliation group: ")
return "", errors.New("Invalid affiliation group " + affiliation)
}
......@@ -576,7 +581,7 @@ func (ca *CA) validateAndGenerateEnrollID(id, affiliation string, role pb.Role)
func (ca *CA) registerUser(id, affiliation string, role pb.Role, registrar, memberMetadata string, opt ...string) (string, error) {
memberMetadata = removeQuotes(memberMetadata)
roleStr, _ := MemberRoleToString(role)