tpm : save tpm event logs

When unseal operation fails due to a policy failure, eve tries to find out
which PCR mismatched, while useful, this information can't help diagnosing
the issue in details. By saving tpm event log when sealing the key and when
unseal operation fails, we can further analyze the problem by parsing
and diffing the event logs.

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

Author: shjala

pkg/pillar/cmd/tpmmgr/tpmmgr_test.go

@@ -21,6 +21,7 @@ import (
 	"github.com/google/go-tpm/tpm2"
 	"github.com/google/go-tpm/tpmutil"
 	etpm "github.com/lf-edge/eve/pkg/pillar/evetpm"
+	fileutils "github.com/lf-edge/eve/pkg/pillar/utils/file"
 )
 
 const ecdhCertPem = `
@@ -268,3 +269,79 @@ func TestSealUnsealMismatchReport(t *testing.T) {
 		return
 	}
 }
+
+func TestSealUnsealTpmEventLogCollect(t *testing.T) {
+	_, err := os.Stat(etpm.TpmDevicePath)
+	if err != nil {
+		t.Skip("TPM is not available, skipping the test.")
+	}
+
+	rw, err := tpm2.OpenTPM(etpm.TpmDevicePath)
+	if err != nil {
+		t.Errorf("OpenTPM failed with err: %v", err)
+		return
+	}
+	defer rw.Close()
+
+	// this should write the save the first event log
+	dataToSeal := []byte("secret")
+	if err := etpm.SealDiskKey(dataToSeal, etpm.DiskKeySealingPCRs); err != nil {
+		t.Errorf("Seal operation failed with err: %v", err)
+		return
+	}
+
+	// this won't write to event log, but still triggers saving it on unseal.
+	pcrValue := bytes.Repeat([]byte{0xF}, sha256.Size)
+	if err = tpm2.PCRExtend(rw, tpmutil.Handle(1), tpm2.AlgSHA256, pcrValue, ""); err != nil {
+		t.Errorf("Failed to extend PCR[1]: %v", err)
+		return
+	}
+
+	// this should fail and result in saving the second tpm event log
+	_, err = etpm.UnsealDiskKey(etpm.DiskKeySealingPCRs)
+	if err == nil {
+		t.Errorf("Expected error from UnsealDiskKey, got nil")
+		return
+	}
+
+	// just check for tpm0
+	sealSuccess := fmt.Sprintf(etpm.TpmEvtLogSavePattern, etpm.MeasurementLogSealSuccess, 0)
+	sealFail := fmt.Sprintf(etpm.TpmEvtLogSavePattern, etpm.MeasurementLogUnsealFail, 0)
+	if !fileutils.FileExists(nil, sealSuccess) {
+		t.Errorf("TPM event log \"%s\" not found, Expected to be saved", sealSuccess)
+		return
+	}
+	if !fileutils.FileExists(nil, sealFail) {
+		t.Errorf("TPM event log \"%s\" not found, Expected to be saved", sealFail)
+		return
+	}
+
+	// this should trigger collecting previous tpm event logs
+	if err := etpm.SealDiskKey(dataToSeal, etpm.DiskKeySealingPCRs); err != nil {
+		t.Errorf("Seal operation failed with err: %v", err)
+		return
+	}
+
+	// current event log should exist
+	if !fileutils.FileExists(nil, sealSuccess) {
+		t.Errorf("TPM event log \"%s\" not found, Expected to be saved", sealSuccess)
+		return
+	}
+	// this shouldn't exist because SealDiskKey will do a clean up
+	if fileutils.FileExists(nil, sealFail) {
+		t.Errorf("TPM event log \"%s\" found, Expected to not exist", sealFail)
+		return
+	}
+
+	// collected event logs both should exist
+	prevSealSuccess := fmt.Sprintf(etpm.TpmEvtLogCollectPattern, sealSuccess)
+	prevSealFail := fmt.Sprintf(etpm.TpmEvtLogCollectPattern, sealFail)
+	if !fileutils.FileExists(nil, prevSealSuccess) {
+		t.Errorf("TPM event log \"%s\" not found, Expected to be collected", prevSealSuccess)
+		return
+	}
+	if !fileutils.FileExists(nil, prevSealFail) {
+		t.Errorf("TPM event log \"%s\" not found, Expected to be collected", prevSealFail)
+		return
+	}
+}

pkg/pillar/evetpm/tpm.go

@@ -16,6 +16,7 @@ import (
 	"io/ioutil"
 	"math/big"
 	"os"
+	"path/filepath"
 	"sort"
 	"unsafe"
 
@@ -77,6 +78,29 @@ const (
 	// TpmSavedDiskSealingPcrs is the file that holds a copy of PCR values
 	// at the time of generating and sealing the disk key into the TPM.
 	TpmSavedDiskSealingPcrs = types.PersistStatusDir + "/sealingpcrs"
+
+	// MeasurementLogSealSuccess is files that holds a copy of event log at the time
+	// of generating/sealing the disk key into the TPM.
+	MeasurementLogSealSuccess = types.PersistStatusDir + "/tpm_measurement_seal_success"
+
+	// MeasurementLogUnsealFail is files that holds a copy of event log at the time EVE
+	// fails to unseal the vault key from TPM.
+	MeasurementLogUnsealFail = types.PersistStatusDir + "/tpm_measurement_unseal_fail"
+
+	// TpmEvtLogSavePattern contains the pattern used to save event log files,
+	// considering the case when multiple tpm devices are present.
+	TpmEvtLogSavePattern = "%s-tpm%d"
+
+	// TpmEvtLogCollectPattern contains the pattern used to collect event log files.
+	TpmEvtLogCollectPattern = "%s-backup"
+
+	// measurementLogFile is a kernel exposed variable that contains the
+	// TPM measurements and events log.
+	measurementLogFile = "binary_bios_measurements"
+
+	// syfsTpmDir is directory that TPMs get mapped on sysfs, and it contains
+	// measurement logs.
+	syfsTpmDir = "/hostfs/sys/kernel/security/tpm*"
 )
 
 // PCRBank256Status stores info about support for
@@ -628,11 +652,31 @@ func SealDiskKey(key []byte, pcrSel tpm2.PCRSelection) error {
 		return fmt.Errorf("NVWrite %v failed: %v", TpmSealedDiskPubHdl, err)
 	}
 
-	// save a snapshot of PCR values
+	// save a snapshot of current PCR values
 	if err := saveDiskKeySealingPCRs(TpmSavedDiskSealingPcrs); err != nil {
 		return fmt.Errorf("saving snapshot of sealing PCRs failed: %w", err)
 	}
 
+	// Backup the previous pair of logs if any, so at most we have two pairs of
+	// measurement logs (per available tpm devices). This is needed because if the
+	// failing devices get connected to the controller and collects the backup key,
+	// we end up here again and will override the MeasurementLogSealSuccess  with
+	// current measurement log (which is same as the content of MeasurementLogSealFail)
+	// and lose the ability to diff and diagnose the issue.
+	if err := backupCopiedMeasurementLogs(); err != nil {
+		return fmt.Errorf("collecting previous snapshot of TPM event log failed: %w", err)
+	}
+
+	// fresh start, remove old copies of measurement logs.
+	if err := removeCopiedMeasurementLogs(); err != nil {
+		return fmt.Errorf("removing old copies of TPM measurement log failed: %w", err)
+	}
+
+	// save a copy of the current measurement log
+	if err := copyMeasurementLog(MeasurementLogSealSuccess); err != nil {
+		return fmt.Errorf("copying current TPM measurement log failed: %w", err)
+	}
+
 	return nil
 }
 
@@ -688,14 +732,22 @@ func UnsealDiskKey(pcrSel tpm2.PCRSelection) ([]byte, error) {
 
 	key, err := tpm2.UnsealWithSession(rw, session, sealedObjHandle, EmptyPassword)
 	if err != nil {
-		// We get here mostly because of RCPolicyFail error, so try to get more
-		// information about the failure by finding the mismatching PCR index.
-		mismatch, extraErr := findMismatchingPCRs(TpmSavedDiskSealingPcrs)
-		if extraErr != nil {
-			return nil, fmt.Errorf("UnsealWithSession failed: %w, getting more info failed: %v", err, extraErr)
+		// We get here mostly because of RCPolicyFail error, so first try to save
+		// a copy of TPM measurement log, it comes handy for diagnosing the issue.
+		evtLogStat := "copied (failed unseal) TPM measurement log"
+		if errEvtLog := copyMeasurementLog(MeasurementLogUnsealFail); errEvtLog != nil {
+			// just report the failure, still give findMismatchingPCRs a chance so
+			// we can at least have some partial information about why unseal failed.
+			evtLogStat = fmt.Sprintf("copying (failed unseal) TPM measurement log failed: %v", errEvtLog)
+		}
+
+		// try to find out the mismatching PCR index
+		mismatch, errPcrMiss := findMismatchingPCRs(TpmSavedDiskSealingPcrs)
+		if errPcrMiss != nil {
+			return nil, fmt.Errorf("UnsealWithSession failed: %w, %s, finding mismatching PCR failed: %v", err, evtLogStat, errPcrMiss)
 		}
 
-		return nil, fmt.Errorf("UnsealWithSession failed: %w, possibly mismatching PCR indexes %v", err, mismatch)
+		return nil, fmt.Errorf("UnsealWithSession failed: %w, %s, possibly mismatching PCR indexes: %v", err, evtLogStat, mismatch)
 	}
 	return key, nil
 }
@@ -805,6 +857,124 @@ func pcrBankSHA256EnabledHelper() bool {
 	return err == nil
 }
 
+func getMappedTpmsPath() ([]string, error) {
+	paths, err := filepath.Glob(syfsTpmDir)
+	if err != nil {
+		return nil, fmt.Errorf("failed to enumerate TPM(s) in sysfs: %w", err)
+	} else if len(paths) == 0 {
+		return nil, fmt.Errorf("found no TPM in sysfs")
+	}
+
+	return paths, nil
+}
+
+func countMappedTpms() (int, error) {
+	paths, err := getMappedTpmsPath()
+	if err != nil {
+		return 0, fmt.Errorf("getMappedTpmsPath failed: %w", err)
+	}
+
+	return len(paths), nil
+}
+
+func getMeasurementLogFiles() ([]string, error) {
+	paths, err := getMappedTpmsPath()
+	if err != nil {
+		return nil, fmt.Errorf("getMappedTpmsPath failed: %w", err)
+	}
+
+	enumerated := make([]string, 0)
+	for _, path := range paths {
+		fullPath := filepath.Join(path, measurementLogFile)
+		if fileutils.FileExists(nil, fullPath) {
+			enumerated = append(enumerated, fullPath)
+		}
+	}
+
+	return enumerated, nil
+}
+
+func backupCopiedMeasurementLogs() error {
+	counted, err := countMappedTpms()
+	if err != nil {
+		return fmt.Errorf("countMappedTPMs failed: %w", err)
+	}
+
+	leftToBackup := counted
+	for i := 0; i < counted; i++ {
+		sealSuccessPath := fmt.Sprintf(TpmEvtLogSavePattern, MeasurementLogSealSuccess, i)
+		unsealFailPath := fmt.Sprintf(TpmEvtLogSavePattern, MeasurementLogUnsealFail, i)
+		if fileutils.FileExists(nil, sealSuccessPath) && fileutils.FileExists(nil, unsealFailPath) {
+			sealSuccessBackupPath := fmt.Sprintf(TpmEvtLogCollectPattern, sealSuccessPath)
+			unsealFailBackupPath := fmt.Sprintf(TpmEvtLogCollectPattern, unsealFailPath)
+			if err := os.Rename(sealSuccessPath, sealSuccessBackupPath); err != nil {
+				fmt.Fprintf(os.Stderr, "failed to backup tpm%d \"seal success\" previously copied measurement log: %v", i, err)
+				continue
+			}
+			if err := os.Rename(unsealFailPath, unsealFailBackupPath); err != nil {
+				fmt.Fprintf(os.Stderr, "failed to backup tpm%d \"unseal fail\" previously copied measurement log: %v", i, err)
+				_ = os.Rename(sealSuccessBackupPath, sealSuccessPath)
+				continue
+			}
+		}
+
+		leftToBackup--
+	}
+
+	if leftToBackup != 0 {
+		return fmt.Errorf("failed to backup %d number of previously copied TPM measurement logs", leftToBackup)
+	}
+
+	return nil
+}
+
+func removeCopiedMeasurementLogs() error {
+	counted, err := countMappedTpms()
+	if err != nil {
+		return fmt.Errorf("countMappedTPMs failed: %w", err)
+	}
+
+	for i := 0; i < counted; i++ {
+		sealSuccessPath := fmt.Sprintf(TpmEvtLogSavePattern, MeasurementLogSealSuccess, i)
+		unsealFailPath := fmt.Sprintf(TpmEvtLogSavePattern, MeasurementLogUnsealFail, i)
+		_ = os.Remove(sealSuccessPath)
+		_ = os.Remove(unsealFailPath)
+	}
+
+	return nil
+}
+
+func copyMeasurementLog(dstPath string) error {
+	paths, err := getMeasurementLogFiles()
+	if err != nil {
+		return fmt.Errorf("enumSourceEventLogFiles failed: %w", err)
+	}
+
+	leftToCopy := len(paths)
+	for i, path := range paths {
+		measurementLogContent, err := os.ReadFile(path)
+		if err != nil {
+			fmt.Fprintf(os.Stderr, "failed to read stored measurement log file: %v", err)
+			continue
+		}
+
+		copyPath := fmt.Sprintf(TpmEvtLogSavePattern, dstPath, i)
+		err = fileutils.WriteRename(copyPath, measurementLogContent)
+		if err != nil {
+			fmt.Fprintf(os.Stderr, "failed to copy stored measurement log file: %v", err)
+			continue
+		}
+
+		leftToCopy--
+	}
+
+	if leftToCopy != 0 {
+		return fmt.Errorf("failed to copy %d number of stored measurement log files", leftToCopy)
+	}
+
+	return nil
+}
+
 func saveDiskKeySealingPCRs(pcrsFile string) error {
 	trw, err := tpm2.OpenTPM(TpmDevicePath)
 	if err != nil {