treewide: better log messages and fixes

attestationreport/tpm.go

@@ -183,6 +183,8 @@ func recalculatePcrs(tpmM *TpmMeasurement, referenceValues []ReferenceValue) (ma
 					}
 				}
 				if !found {
+					log.Warnf("Failed to find reference value %v in measurements",
+						hex.EncodeToString(ref.Sha256))
 					ok = false
 					refResult.Success = false
 					refResult.Type = "Reference Value"
@@ -226,6 +228,8 @@ func recalculatePcrs(tpmM *TpmMeasurement, referenceValues []ReferenceValue) (ma
 								Type:    "Measurement",
 							}
 							artifacts = append(artifacts, measResult)
+							log.Warnf("Failed to find measurement %v in reference values",
+								hex.EncodeToString(sha256))
 							ok = false
 						}
 					}
@@ -237,6 +241,8 @@ func recalculatePcrs(tpmM *TpmMeasurement, referenceValues []ReferenceValue) (ma
 					pcrRes.Success = true
 					pcrRes.Calculated = hex.EncodeToString(measurement)
 				} else {
+					log.Warnf("PCR%v mismatch: measured: %v, calculated: %v", pcrNum,
+						hex.EncodeToString(measurement), hex.EncodeToString(calculatedHash))
 					pcrRes.Success = false
 					pcrRes.Calculated = hex.EncodeToString(calculatedHash)
 					pcrRes.Measured = hex.EncodeToString(measurement)
@@ -262,6 +268,7 @@ func recalculatePcrs(tpmM *TpmMeasurement, referenceValues []ReferenceValue) (ma
 					artifacts[i].Success = false
 				}
 			}
+			log.Warnf("Measurement did not contain PCR%v", pcrNum)
 			ok = false
 		}
 	}

attestedtls/attestation.go

@@ -51,8 +51,7 @@ func attestDialer(conn *tls.Conn, chbindings []byte, cc cmcConfig) error {
 		if err != nil {
 			return fmt.Errorf("failed to send skip client Attestation: %w", err)
 		}
-		log.Debug("Sent skip response")
-		log.Debug("Skipping, Server only attestation: client side attestation only")
+		log.Debug("Skipping client-side attestation")
 	}
 
 	readvalue, err := readValue(conn, cc.attest, true)
@@ -62,8 +61,6 @@ func attestDialer(conn *tls.Conn, chbindings []byte, cc cmcConfig) error {
 
 	//optional: Wait for attestation report from Server
 	if cc.attest == Attest_Mutual || cc.attest == Attest_Server {
-		log.Trace("Attesting the Server")
-
 		report := readvalue
 		// Verify AR from listener with own channel bindings
 		log.Trace("Verifying attestation report from listener")
@@ -72,7 +69,7 @@ func attestDialer(conn *tls.Conn, chbindings []byte, cc cmcConfig) error {
 			return err
 		}
 	} else {
-		log.Debug("Skipping, Client only attestation: client side attestation only")
+		log.Debug("Skipping client-side verification")
 	}
 
 	log.Trace("Attestation successful")
@@ -102,8 +99,7 @@ func attestListener(conn *tls.Conn, chbindings []byte, cc cmcConfig) error {
 		if err != nil {
 			return fmt.Errorf("failed to send skip client Attestation: %w", err)
 		}
-		log.Debug("Sent skip response")
-		log.Debug("Skipping, Client only attestation: client side attestation only")
+		log.Debug("Skipping server-side attestation")
 	}
 
 	readValue, err := readValue(conn, cc.attest, false)
@@ -113,7 +109,6 @@ func attestListener(conn *tls.Conn, chbindings []byte, cc cmcConfig) error {
 
 	// optional: Wait for attestation report from client
 	if cc.attest == Attest_Mutual || cc.attest == Attest_Client {
-		log.Debug("Attesting the Client")
 		report := readValue
 		// Verify AR from dialer with own channel bindings
 		log.Trace("Verifying attestation report from dialer...")
@@ -122,7 +117,7 @@ func attestListener(conn *tls.Conn, chbindings []byte, cc cmcConfig) error {
 			return err
 		}
 	} else {
-		log.Debug("Skipping, Server only attestation: server side attestation only")
+		log.Debug("Skipping server-side verification")
 	}
 
 	log.Trace("Attestation successful")
@@ -143,7 +138,7 @@ func readValue(conn *tls.Conn, selection AttestSelect, dialer bool) ([]byte, err
 
 	// the first byte should always be the attestation mode
 	if readvalue[0] == byte(selection) {
-		log.Debug("Matching attestation mode, both are set to:", selectionStr)
+		log.Debugf("Matching attestation mode: [%v]", selectionStr)
 	} else {
 		reportByte := readvalue[0]
 		reportStr, errS1 := selectionString(reportByte)

testtool/internal.go

@@ -55,13 +55,15 @@ func dialInternalAddr(c *config, api atls.CmcApiSelect, addr string, tlsConf *tl
 		atls.WithResult(verificationResult),
 		atls.WithCmc(cmc))
 	// Publish the attestation result asynchronously if publishing address was specified and
-	// the result is present
-	wg := new(sync.WaitGroup)
-	wg.Add(1)
-	defer wg.Wait()
-	go publishResultAsync(c.Publish, verificationResult, wg)
-	if err != nil {
-		return fmt.Errorf("failed to dial server: %v", err)
+	// and attestation was performed
+	if c.Publish != "" && (c.Attest == "mutual" || c.Attest == "server") {
+		wg := new(sync.WaitGroup)
+		wg.Add(1)
+		defer wg.Wait()
+		go publishResultAsync(c.Publish, verificationResult, wg)
+		if err != nil {
+			return fmt.Errorf("failed to dial server: %v", err)
+		}
 	}
 	defer conn.Close()
 	_ = conn.SetReadDeadline(time.Now().Add(timeoutSec * time.Second))
@@ -230,7 +232,7 @@ func listenInternal(c *config, api atls.CmcApiSelect, cmc *cmc.Cmc) {
 		// Handle established connections
 		go handleConnection(conn)
 
-		if c.Mtls {
+		if c.Publish != "" && (c.Attest == "mutual" || c.Attest == "client") {
 			// Publish the attestation result if publishing address was specified
 			// and result is not empty
 			go publishResult(c.Publish, verificationResult)

tpmdriver/bioseventlog.go

@@ -20,7 +20,7 @@ import (
 	"encoding/binary"
 	"errors"
 	"fmt"
-	"io/ioutil"
+	"os"
 
 	ar "github.com/Fraunhofer-AISEC/cmc/attestationreport"
 )
@@ -110,9 +110,9 @@ type TPMT_HA struct {
 // measurements (usually /sys/kernel/security/tpm0/binary_bios_measurements)
 // must be specified
 func GetBiosMeasurements(file string) ([]ar.ReferenceValue, error) {
-	data, err := ioutil.ReadFile(file)
+	data, err := os.ReadFile(file)
 	if err != nil {
-		return nil, fmt.Errorf("failed to load IMA runtime measurements from %v: %w", file, err)
+		return nil, fmt.Errorf("failed to read %v: %w", file, err)
 	}
 
 	digests, err := parseBiosMeasurements(data)