Use logrus features for better logging

2017-09-07 10:49:27 -07:00 · 2017-09-07 10:49:27 -07:00 · 55c7174713
--- a/aes/decryptor.go
+++ b/aes/decryptor.go
@ -11,12 +11,13 @@ import (
 	"strings"

 	"github.com/sirupsen/logrus"
+	"go.mozilla.org/sops/logging"
 )

 var log *logrus.Logger

 func init() {
-	log = logrus.New()
+	log = logging.NewLogger("AES")
 }

 type encryptedValue struct {
--- a/cmd/sops/main.go
+++ b/cmd/sops/main.go
@ -27,6 +27,7 @@ import (
 	"go.mozilla.org/sops/keys"
 	"go.mozilla.org/sops/keyservice"
 	"go.mozilla.org/sops/kms"
+	"go.mozilla.org/sops/logging"
 	"go.mozilla.org/sops/pgp"
 	"go.mozilla.org/sops/stores/json"
 	yamlstores "go.mozilla.org/sops/stores/yaml"
@ -37,7 +38,7 @@ import (
 var log *logrus.Logger

 func init() {
-	log = logrus.New()
+	log = logging.NewLogger("CMD")
 }

 func main() {
@ -432,19 +433,22 @@ func main() {
 		}
 		// We open the file *after* the operations on the tree have been
 		// executed to avoid truncating it when there's errors
-		var outputFile *os.File
 		if c.Bool("in-place") || isEditMode || c.String("set") != "" {
-			var err error
-			outputFile, err = os.Create(fileName)
+			file, err := os.Create(fileName)
 			if err != nil {
 				return cli.NewExitError(fmt.Sprintf("Could not open in-place file for writing: %s", err), codes.CouldNotWriteOutputFile)
 			}
-			defer outputFile.Close()
+			defer file.Close()
+			_, err = file.Write(output)
+			if err != nil {
+				return err
+			}
+			log.Info("File written successfully")
+			return nil
 		} else {
-			outputFile = os.Stdout
+			_, err = os.Stdout.Write(output)
+			return err
 		}
-		outputFile.Write(output)
-		return nil
 	}
 	app.Run(os.Args)
 }
--- a/cmd/sops/subcommand/keyservice/keyservice.go
+++ b/cmd/sops/subcommand/keyservice/keyservice.go
@ -7,6 +7,7 @@ import (
 	"syscall"

 	"go.mozilla.org/sops/keyservice"
+	"go.mozilla.org/sops/logging"

 	"github.com/sirupsen/logrus"
 	"google.golang.org/grpc"
@ -15,7 +16,7 @@ import (
 var log *logrus.Logger

 func init() {
-	log = logrus.New()
+	log = logging.NewLogger("KEYSERVICE")
 }

 type Opts struct {
--- a/decrypt/example_test.go
+++ b/decrypt/example_test.go
@ -3,13 +3,15 @@ package decrypt
 import (
 	"encoding/json"

+	"go.mozilla.org/sops/logging"
+
 	"github.com/sirupsen/logrus"
 )

 var log *logrus.Logger

 func init() {
-	log = logrus.New()
+	log = logging.NewLogger("DECRYPT")
 }

 type configuration struct {
--- a/kms/keysource.go
+++ b/kms/keysource.go
@ -8,6 +8,8 @@ import (
 	"strings"
 	"time"

+	"go.mozilla.org/sops/logging"
+
 	"github.com/aws/aws-sdk-go/aws"
 	"github.com/aws/aws-sdk-go/aws/credentials"
 	"github.com/aws/aws-sdk-go/aws/credentials/stscreds"
@ -21,7 +23,7 @@ import (
 var log *logrus.Logger

 func init() {
-	log = logrus.New()
+	log = logging.NewLogger("KMS")
 }

 // this needs to be a global var for unit tests to work (mockKMS redefines
@ -48,24 +50,23 @@ func (key *MasterKey) SetEncryptedDataKey(enc []byte) {

 // Encrypt takes a sops data key, encrypts it with KMS and stores the result in the EncryptedKey field
 func (key *MasterKey) Encrypt(dataKey []byte) error {
-	log.Printf("Attempting encryption of KMS MasterKey with ARN %s", key.Arn)
 	// isMocked is set by unit test to indicate that the KMS service
 	// has already been initialized. it's ugly, but it works.
 	if kmsSvc == nil || !isMocked {
 		sess, err := key.createSession()
 		if err != nil {
-			log.Printf("Encryption of KMS MasterKey with ARN %s failed", key.Arn)
+			log.WithField("arn", key.Arn).Warn("Encryption failed")
 			return fmt.Errorf("Failed to create session: %v", err)
 		}
 		kmsSvc = kms.New(sess)
 	}
 	out, err := kmsSvc.Encrypt(&kms.EncryptInput{Plaintext: dataKey, KeyId: &key.Arn, EncryptionContext: key.EncryptionContext})
 	if err != nil {
-		log.Printf("Encryption of KMS MasterKey with ARN %s failed", key.Arn)
+		log.WithField("arn", key.Arn).Warn("Encryption failed")
 		return fmt.Errorf("Failed to call KMS encryption service: %v", err)
 	}
 	key.EncryptedKey = base64.StdEncoding.EncodeToString(out.CiphertextBlob)
-	log.Printf("Encryption of KMS MasterKey with ARN %s succeeded", key.Arn)
+	log.WithField("arn", key.Arn).Info("Encryption succeeded")
 	return nil
 }

@ -79,10 +80,9 @@ func (key *MasterKey) EncryptIfNeeded(dataKey []byte) error {

 // Decrypt decrypts the EncryptedKey field with AWS KMS and returns the result.
 func (key *MasterKey) Decrypt() ([]byte, error) {
-	log.Printf("Attempting decryption of KMS MasterKey with ARN %s", key.Arn)
 	k, err := base64.StdEncoding.DecodeString(key.EncryptedKey)
 	if err != nil {
-		log.Printf("Decryption of KMS MasterKey with ARN %s failed", key.Arn)
+		log.WithField("arn", key.Arn).Warn("Decryption failed")
 		return nil, fmt.Errorf("Error base64-decoding encrypted data key: %s", err)
 	}
 	// isMocked is set by unit test to indicate that the KMS service
@ -90,17 +90,17 @@ func (key *MasterKey) Decrypt() ([]byte, error) {
 	if kmsSvc == nil || !isMocked {
 		sess, err := key.createSession()
 		if err != nil {
-			log.Printf("Decryption of KMS MasterKey with ARN %s failed", key.Arn)
+			log.WithField("arn", key.Arn).Warn("Decryption failed")
 			return nil, fmt.Errorf("Error creating AWS session: %v", err)
 		}
 		kmsSvc = kms.New(sess)
 	}
 	decrypted, err := kmsSvc.Decrypt(&kms.DecryptInput{CiphertextBlob: k, EncryptionContext: key.EncryptionContext})
 	if err != nil {
-		log.Printf("Decryption of KMS MasterKey with ARN %s failed", key.Arn)
+		log.WithField("arn", key.Arn).Warn("Decryption failed")
 		return nil, fmt.Errorf("Error decrypting key: %v", err)
 	}
-	log.Printf("Decryption of KMS MasterKey with ARN %s succeeded", key.Arn)
+	log.WithField("arn", key.Arn).Info("Decryption succeeded")
 	return decrypted.Plaintext, nil
 }

@ -215,7 +215,7 @@ func ParseKMSContext(in interface{}) map[string]*string {
 		for k, v := range in {
 			value, ok := v.(string)
 			if !ok {
-				log.Println("[WARNING]: KMS Encryption Context contains a non-string value, context will not be used")
+				log.Warn("Encryption context contains a non-string value, context will not be used")
 				return nil
 			}
 			out[k] = &value
@ -227,12 +227,12 @@ func ParseKMSContext(in interface{}) map[string]*string {
 		for k, v := range in {
 			key, ok := k.(string)
 			if !ok {
-				log.Println("[WARNING]: KMS Encryption Context contains a non-string key, context will not be used")
+				log.Warn("Encryption context contains a non-string value, context will not be used")
 				return nil
 			}
 			value, ok := v.(string)
 			if !ok {
-				log.Println("[WARNING]: KMS Encryption Context contains a non-string value, context will not be used")
+				log.Warn("Encryption context contains a non-string value, context will not be used")
 				return nil
 			}
 			out[key] = &value
@ -244,7 +244,7 @@ func ParseKMSContext(in interface{}) map[string]*string {
 		for _, kv := range strings.Split(in, ",") {
 			kv := strings.Split(kv, ":")
 			if len(kv) != 2 {
-				log.Printf("[WARNING]: KMS Encryption Context could not be parsed, context will not be used")
+				log.Warn("Encryption context contains a non-string value, context will not be used")
 				return nil
 			}
 			out[kv[0]] = &kv[1]
--- a/logging/logging.go
+++ b/logging/logging.go
@ -0,0 +1,35 @@
+package logging
+
+import (
+	"fmt"
+
+	"github.com/fatih/color"
+	"github.com/sirupsen/logrus"
+)
+
+func init() {
+	Loggers = make(map[string]*logrus.Logger)
+}
+
+// TextFormatter extends the standard logrus TextFormatter and adds a field to specify the logger's name
+type TextFormatter struct {
+	LoggerName string
+	logrus.TextFormatter
+}
+
+func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) {
+	bytes, err := f.TextFormatter.Format(entry)
+	name := color.New(color.Bold).Sprintf("[%s]", f.LoggerName)
+	return []byte(fmt.Sprintf("%s\t %s", name, bytes)), err
+}
+
+func NewLogger(name string) *logrus.Logger {
+	log := logrus.New()
+	log.Formatter = &TextFormatter{
+		LoggerName: name,
+	}
+	Loggers[name] = log
+	return log
+}
+
+var Loggers map[string]*logrus.Logger
--- a/pgp/keysource.go
+++ b/pgp/keysource.go
@ -16,6 +16,7 @@ import (
 	"github.com/howeyc/gopass"
 	"github.com/sirupsen/logrus"
 	gpgagent "go.mozilla.org/gopgagent"
+	"go.mozilla.org/sops/logging"
 	"golang.org/x/crypto/openpgp"
 	"golang.org/x/crypto/openpgp/armor"
 )
@ -23,7 +24,7 @@ import (
 var log *logrus.Logger

 func init() {
-	log = logrus.New()
+	log = logging.NewLogger("PGP")
 }

 // MasterKey is a PGP key used to securely store sops' data key by encrypting it and decrypting it
@ -115,19 +116,17 @@ func (key *MasterKey) encryptWithCryptoOpenPGP(dataKey []byte) error {

 // Encrypt encrypts the data key with the PGP key with the same fingerprint as the MasterKey. It looks for PGP public keys in $PGPHOME/pubring.gpg.
 func (key *MasterKey) Encrypt(dataKey []byte) error {
-	log.Printf("Attempting encryption of GPG MasterKey with fingerprint %s", key.Fingerprint)
 	openpgpErr := key.encryptWithCryptoOpenPGP(dataKey)
 	if openpgpErr == nil {
-		log.Printf("Encryption of GPG MasterKey with fingerprint %s succeeded", key.Fingerprint)
+		log.WithField("fingerprint", key.Fingerprint).Info("Encryption succeeded")
 		return nil
 	}
-	log.Print("Encryption with golang's openpgp package failed, falling back to the GPG binary")
 	binaryErr := key.encryptWithGPGBinary(dataKey)
 	if binaryErr == nil {
-		log.Printf("Encryption of GPG MasterKey with fingerprint %s succeeded", key.Fingerprint)
+		log.WithField("fingerprint", key.Fingerprint).Info("Encryption succeeded")
 		return nil
 	}
-	log.Printf("Encryption of GPG MasterKey with fingerprint %s failed", key.Fingerprint)
+	log.WithField("fingerprint", key.Fingerprint).Warn("Encryption failed")
 	return fmt.Errorf(`could not encrypt data key with PGP key.
 	\tgolang.org/x/crypto/openpgp error: %s
 	\tGPG binary error: %s`, openpgpErr, binaryErr)
@ -172,7 +171,6 @@ func (key *MasterKey) decryptWithCryptoOpenpgp() ([]byte, error) {
 		return nil, fmt.Errorf("Reading PGP message failed: %s", err)
 	}
 	if b, err := ioutil.ReadAll(md.UnverifiedBody); err == nil {
-		log.Printf("Decryption of GPG MasterKey with fingerprint %s successful", key.Fingerprint)
 		return b, nil
 	}
 	return nil, fmt.Errorf("The key could not be decrypted with any of the GPG entries")
@ -180,19 +178,17 @@ func (key *MasterKey) decryptWithCryptoOpenpgp() ([]byte, error) {

 // Decrypt uses PGP to obtain the data key from the EncryptedKey store in the MasterKey and returns it
 func (key *MasterKey) Decrypt() ([]byte, error) {
-	log.Printf("Attempting decryption of GPG MasterKey with fingerprint %s", key.Fingerprint)
 	dataKey, openpgpErr := key.decryptWithCryptoOpenpgp()
 	if openpgpErr == nil {
-		log.Printf("Decryption of GPG MasterKey with fingerprint %s succeeded", key.Fingerprint)
+		log.WithField("fingerprint", key.Fingerprint).Info("Decryption succeeded")
 		return dataKey, nil
 	}
-	log.Print("Decryption with golang's openpgp package failed, falling back to the GPG binary")
 	dataKey, binaryErr := key.decryptWithGPGBinary()
 	if binaryErr == nil {
-		log.Printf("Decryption of GPG MasterKey with fingerprint %s succeeded", key.Fingerprint)
+		log.WithField("fingerprint", key.Fingerprint).Info("Decryption succeeded")
 		return dataKey, nil
 	}
-	log.Printf("Decryption of GPG MasterKey with fingerprint %s failed", key.Fingerprint)
+	log.WithField("fingerprint", key.Fingerprint).Info("Decryption failed")
 	return nil, fmt.Errorf(`could not encrypt data key with PGP key.
 	\tgolang.org/x/crypto/openpgp error: %s
 	\tGPG binary error: %s`, openpgpErr, binaryErr)
@ -276,7 +272,7 @@ func (key *MasterKey) passphrasePrompt(keys []openpgp.Key, symmetric bool) ([]by
 	conn, err := gpgagent.NewConn()
 	if err == gpgagent.ErrNoAgent {
 		log.Printf("gpg-agent not found, continuing with manual passphrase input...")
-		log.Print("Enter PGP key passphrase: ")
+		fmt.Print("Enter PGP key passphrase: ")
 		pass, err := gopass.GetPasswd()
 		if err != nil {
 			return nil, err
--- a/sops.go
+++ b/sops.go
@ -49,6 +49,7 @@ import (

 	"go.mozilla.org/sops/keys"
 	"go.mozilla.org/sops/keyservice"
+	"go.mozilla.org/sops/logging"
 	"go.mozilla.org/sops/shamir"
 	"golang.org/x/net/context"
 )
@ -71,7 +72,7 @@ const MetadataNotFound = sopsError("sops metadata not found")
 var log *logrus.Logger

 func init() {
-	log = logrus.New()
+	log = logging.NewLogger("SOPS")
 }

 // DataKeyCipher provides a way to encrypt and decrypt the data key used to encrypt and decrypt sops files, so that the data key can be stored alongside the encrypted content. A DataKeyCipher must be able to decrypt the values it encrypts.
@ -119,7 +120,7 @@ type Tree struct {

 // Truncate truncates the tree to the path specified
 func (tree TreeBranch) Truncate(path []interface{}) (interface{}, error) {
-	log.Printf("Truncating tree to %s", path)
+	log.WithField("path", path).Info("Truncating tree")
 	var current interface{} = tree
 	for _, component := range path {
 		switch component := component.(type) {
@ -242,7 +243,7 @@ func (tree Tree) Encrypt(key []byte, cipher DataKeyCipher, stash map[string][]in

 // Decrypt walks over the tree and decrypts all values with the provided cipher, except those whose key ends with the UnencryptedSuffix specified on the Metadata struct. If decryption is successful, it returns the MAC for the decrypted tree.
 func (tree Tree) Decrypt(key []byte, cipher DataKeyCipher, stash map[string][]interface{}) (string, error) {
-	log.Print("Decrypting SOPS tree")
+	log.Debug("Decrypting tree")
 	hash := sha512.New()
 	_, err := tree.Branch.walkBranch(tree.Branch, make([]string, 0), func(in interface{}, path []string) (interface{}, error) {
 		var v interface{}
@ -348,7 +349,10 @@ func (m *Metadata) UpdateMasterKeysWithKeyServices(dataKey []byte, svcs []keyser
 		if m.ShamirQuorum == 0 {
 			m.ShamirQuorum = len(m.KeyGroups)
 		}
-		log.Printf("Multiple KeyGroups found, proceeding with Shamir with quorum %d", m.ShamirQuorum)
+		log.WithFields(logrus.Fields{
+			"quorum": m.ShamirQuorum,
+			"parts":  len(m.KeyGroups),
+		}).Info("Splitting data key with Shamir Secret Sharing")
 		parts, err = shamir.Split(dataKey, len(m.KeyGroups), int(m.ShamirQuorum))
 		if err != nil {
 			errs = append(errs, fmt.Errorf("Could not split data key into parts for Shamir: %s", err))
@ -442,6 +446,7 @@ func (m Metadata) GetDataKeyWithKeyServices(svcs []keyservice.KeyServiceClient)
 		}
 		dataKey = parts[0]
 	}
+	log.Info("Data key recovered successfully")
 	m.DataKey = dataKey
 	return dataKey, nil
 }