tpm : streamline the error massges

Signed-off-by: Shahriyar Jalayeri <[email protected]>

Author: shjala

pkg/pillar/cmd/vaultmgr/vaultmgr.go

@@ -260,18 +260,27 @@ func Run(ps *pubsub.PubSub, loggerArg *logrus.Logger, logArg *base.LogObject, ar
 
 	// initialize publishing handles
 	initializeSelfPublishHandles(ps, &ctx)
-	if etpm.IsTpmEnabled() {
+	tpmEnabled := etpm.IsTpmEnabled()
+	if tpmEnabled {
 		// TPM is enabled. Check if defaultVault directory exists, if not set vaultconfig
 		tpmKeyOnlyMode := checkAndPublishVaultConfig(&ctx)
 		handler.SetHandlerOptions(vault.HandlerOptions{TpmKeyOnlyMode: tpmKeyOnlyMode})
 	}
+
+	if tpmEnabled {
+		log.Noticef("about to setup the vault and fetch the disk key from TPM")
+	} else {
+		log.Noticef("about to setup the vault without TPM")
+	}
+	// if TPM available, this sets up the fscrypt and eventually calls FetchSealedVaultKey
 	if err := handler.SetupDefaultVault(); err != nil {
-		log.Errorf("setupDefaultVault failed, err: %v", err)
+		log.Errorf("SetupDefaultVault failed, err: %v", err)
 		getAndPublishAllVaultStatuses(&ctx)
 	} else {
+		log.Noticef("vault is setup and unlocked successfully")
 		ctx.defaultVaultUnlocked = true
 	}
-	if ctx.defaultVaultUnlocked || !etpm.IsTpmEnabled() {
+	if ctx.defaultVaultUnlocked || !tpmEnabled {
 		// Now that vault is unlocked, run any upgrade converter handler if needed
 		// In case of non-TPM platforms, we do this irrespective of
 		// defaultVaultUnlocked

pkg/pillar/evetpm/tpm.go

@@ -189,7 +189,6 @@ func ReadOwnerCrdl() (string, error) {
 // TpmSign is used by external packages to get a digest signed by
 // device key in TPM
 func TpmSign(digest []byte) (*big.Int, *big.Int, error) {
-
 	rw, err := tpm2.OpenTPM(TpmDevicePath)
 	if err != nil {
 		return nil, nil, err
@@ -198,7 +197,7 @@ func TpmSign(digest []byte) (*big.Int, *big.Int, error) {
 
 	tpmOwnerPasswd, err := ReadOwnerCrdl()
 	if err != nil {
-		return nil, nil, fmt.Errorf("Error in fetching TPM credentials: %v", err)
+		return nil, nil, fmt.Errorf("fetching TPM credentials failed: %v", err)
 	}
 
 	//XXX This "32" should really come from Hash algo used.
@@ -213,7 +212,7 @@ func TpmSign(digest []byte) (*big.Int, *big.Int, error) {
 	sig, err := tpm2.Sign(rw, TpmDeviceKeyHdl,
 		tpmOwnerPasswd, digest, nil, scheme)
 	if err != nil {
-		return nil, nil, fmt.Errorf("Sign using TPM failed with error %v", err)
+		return nil, nil, fmt.Errorf("signing data using TPM failed: %v", err)
 	}
 	return sig.ECC.R, sig.ECC.S, nil
 }
@@ -266,7 +265,6 @@ func GetFirmwareVersion(v1 uint32, v2 uint32) string {
 
 // GetTpmProperty fetches a given property id, and returns it as uint32
 func GetTpmProperty(propID tpm2.TPMProp) (uint32, error) {
-
 	rw, err := tpm2.OpenTPM(TpmDevicePath)
 	if err != nil {
 		return 0, err
@@ -280,7 +278,7 @@ func GetTpmProperty(propID tpm2.TPMProp) (uint32, error) {
 	}
 	prop, ok := v[0].(tpm2.TaggedProperty)
 	if !ok {
-		return 0, fmt.Errorf("Unable to fetch property %d", propID)
+		return 0, fmt.Errorf("fetching TPM property %X failed", propID)
 	}
 	return prop.Value, nil
 }
@@ -340,7 +338,6 @@ const (
 
 // FetchTpmHwInfo returns TPM Hardware properties in a string
 func FetchTpmHwInfo() (string, error) {
-
 	//If we had done this earlier, return the last result
 	if tpmHwInfo != "" {
 		return tpmHwInfo, nil
@@ -386,7 +383,7 @@ func FetchVaultKey(log *base.LogObject) ([]byte, error) {
 	//First try to read from TPM, if it was stored earlier
 	key, err := readDiskKey()
 	if err != nil {
-		log.Noticef("Generating VaultKey")
+		log.Noticef("can't read the legacy disk key, generating a new one")
 		//
 		//Note on why we are using GetRandom here:
 		//We are using raw_key option to protect the encryption/decryption protector:
@@ -405,14 +402,14 @@ func FetchVaultKey(log *base.LogObject) ([]byte, error) {
 		//
 		key, err = GetRandom(vaultKeyLength)
 		if err != nil {
-			return nil, fmt.Errorf("FetchVaultKey: Error in GetRandom: %v", err)
+			return nil, fmt.Errorf("GetRandom failed: %v", err)
 		}
 		err = writeDiskKey(key)
 		if err != nil {
-			return nil, fmt.Errorf("FetchVaultKey: Writing Key to TPM failed: %v", err)
+			return nil, fmt.Errorf("writing legacy Key to TPM failed: %v", err)
 		}
 	} else {
-		log.Noticef("Found VaultKey")
+		log.Noticef("successfully read the legacy disk key from TPM")
 	}
 	return key, nil
 }
@@ -484,7 +481,7 @@ func FetchSealedVaultKey(log *base.LogObject) ([]byte, error) {
 	legacyKeyPresent := isLegacyKeyPresent()
 
 	if !sealedKeyPresent && !legacyKeyPresent {
-		log.Noticef("FetchSealedVaultKey generate new key")
+		log.Noticef("neither legacy nor sealed disk key present, generating a fresh key")
 		//Fresh install, generate a new key
 		//
 		//Note on why we are using GetRandom here:
@@ -504,16 +501,18 @@ func FetchSealedVaultKey(log *base.LogObject) ([]byte, error) {
 		//
 		key, err := GetRandom(vaultKeyLength)
 		if err != nil {
-			return nil, fmt.Errorf("FetchSealedVaultKey: GetRandom failed, %v", err)
+			return nil, fmt.Errorf("GetRandom failed: %v", err)
 		}
 		err = SealDiskKey(key, DiskKeySealingPCRs)
 		if err != nil {
-			return nil, fmt.Errorf("FetchSealedVaultKey: Sealing failed: %v", err)
+			return nil, fmt.Errorf("sealing the fresh disk key failed: %v", err)
 		}
+
+		log.Noticef("successfully sealed the fresh disk key into TPM")
 	}
 
 	if !sealedKeyPresent && legacyKeyPresent {
-		log.Noticef("FetchSealedVaultKey legacy present")
+		log.Noticef("only legacy disk key present, using it")
 		//XXX: we need a migration path for existing installations.
 		//hence re-using the current key here. i.e. if we end up creating
 		//a new random key here, and we fail the upgrade, the fallback
@@ -526,20 +525,29 @@ func FetchSealedVaultKey(log *base.LogObject) ([]byte, error) {
 		//Upgrade path will be to first upgrade to a) first release and then b)
 		key, err := readDiskKey()
 		if err != nil {
-			return nil, fmt.Errorf("Error in retrieving old key")
+			return nil, fmt.Errorf("retrieving the legacy disk key from TPM failed: %v", err)
 		}
+
+		log.Noticef("try to convert the legacy key into a sealed key")
+
 		err = SealDiskKey(key, DiskKeySealingPCRs)
 		if err != nil {
-			return nil, fmt.Errorf("FetchSealedVaultKey: Sealing failed: %v", err)
+			return nil, fmt.Errorf("sealing the legacy disk key into TPM failed: %v", err)
 		}
 	}
 	//sealedKeyPresent && !legacyKeyPresent : unseal
 	//sealedKeyPresent && legacyKeyPresent  : unseal
 	if sealedKeyPresent {
-		log.Noticef("FetchSealedVaultKey unseal key")
+		log.Noticef("sealed disk key present int TPM, about to unseal it")
 	}
 	//By this, we have a key sealed into TPM
-	return UnsealDiskKey(DiskKeySealingPCRs)
+	key, err := UnsealDiskKey(DiskKeySealingPCRs)
+	if err == nil {
+		// be more verbose, lets celebrate
+		log.Noticef("successfully unsealed the disk key from TPM")
+	}
+
+	return key, err
 }
 
 // SealDiskKey seals key into TPM2.0, with provided PCRs
@@ -574,12 +582,12 @@ func SealDiskKey(key []byte, pcrSel tpm2.PCRSelection) error {
 
 	//Don't need the handle, we need only the policy for sealing
 	if err := tpm2.FlushContext(rw, session); err != nil {
-		return fmt.Errorf("Unable to flush session handle %v: %v", session, err)
+		return fmt.Errorf("flushing session handle %v failed: %v", session, err)
 	}
 
 	priv, public, err := tpm2.Seal(rw, TpmSRKHdl, EmptyPassword, EmptyPassword, policy, key)
 	if err != nil {
-		return fmt.Errorf("Unable to seal key: %v", err)
+		return fmt.Errorf("sealing the disk key into TPM failed: %v", err)
 	}
 
 	// Define space in NV storage and clean up afterwards or subsequent runs will fail.
@@ -667,7 +675,7 @@ func UnsealDiskKey(pcrSel tpm2.PCRSelection) ([]byte, error) {
 
 	sealedObjHandle, _, err := tpm2.Load(rw, TpmSRKHdl, "", pub, priv)
 	if err != nil {
-		return nil, fmt.Errorf("Load failed: %v", err)
+		return nil, fmt.Errorf("loading the disk key into TPM failed: %v", err)
 	}
 	defer tpm2.FlushContext(rw, sealedObjHandle)
 
@@ -683,7 +691,7 @@ func UnsealDiskKey(pcrSel tpm2.PCRSelection) ([]byte, error) {
 		// information about the failure by finding the mismatching PCR index.
 		mismatch, newErr := findMismatchingPCRs(TpmSavedDiskSealingPcrs)
 		if newErr != nil {
-			return nil, fmt.Errorf("UnsealWithSession failed: %v, failed to get more info: %v", err, newErr)
+			return nil, fmt.Errorf("UnsealWithSession failed: %v, getting more info failed: %v", err, newErr)
 		}
 
 		return nil, fmt.Errorf("UnsealWithSession failed: %v, possibly mismatching PCR indexes %v", err, mismatch)
@@ -717,7 +725,7 @@ func PolicyPCRSession(rw io.ReadWriteCloser, pcrSel tpm2.PCRSelection) (tpmutil.
 
 	policy, err := tpm2.PolicyGetDigest(rw, session)
 	if err != nil {
-		return session, nil, fmt.Errorf("Unable to get policy digest: %v", err)
+		return session, nil, fmt.Errorf("PolicyGetDigest failed: %v", err)
 	}
 	return session, policy, nil
 }

pkg/pillar/vault/handler_ext4.go

@@ -117,7 +117,7 @@ func (h *Ext4Handler) SetupDefaultVault() error {
 		return fmt.Errorf("error in setting up vault %s:%v", defaultVault, err)
 	}
 	// Log the type of key used for unlocking default vault
-	h.log.Noticef("default vault unlocked using key type %s",
+	h.log.Noticef("default vault unlocked using key type: %s",
 		etpm.CompareLegacyandSealedKey().String())
 	return nil
 }