TMP

Signed-off-by: Ciprian Hacman <ciprian@hakman.dev>

Author: hakman

upup/pkg/fi/cloudup/azure/attest.go

@@ -34,6 +34,7 @@ import (
 
 	"github.com/smallstep/pkcs7"
 	expirationcache "k8s.io/client-go/tools/cache"
+	"k8s.io/klog/v2"
 )
 
 const (
@@ -144,9 +145,7 @@ func verifyAttestedDocument(signature string, body []byte) (*attestedData, error
 }
 
 // verifyAttestedDocumentWithRootAndFetcher verifies a PKCS7 attested document
-// using the supplied root pool and intermediate fetcher. It prefers the
-// embedded PKCS7 certificates and only consults the fetcher when the embedded
-// chain does not already verify.
+// using the supplied root pool and intermediate fetcher.
 func verifyAttestedDocumentWithRootAndFetcher(signature string, body []byte, rootCertPool *x509.CertPool, fetchIntermediates func(*x509.Certificate) (*x509.CertPool, error)) (*attestedData, error) {
 	if rootCertPool == nil {
 		return nil, fmt.Errorf("root certificate pool is required")
@@ -160,17 +159,16 @@ func verifyAttestedDocumentWithRootAndFetcher(signature string, body []byte, roo
 		return nil, err
 	}
 
-	embeddedOnlyIntermediates := x509.NewCertPool()
-	if err := verifySignerCertChain(signer, p7.Certificates, rootCertPool, embeddedOnlyIntermediates); err != nil {
-		// Signer SAN was validated above; only now is it safe to hit the network.
-		intermediateCerts, fetchErr := fetchIntermediates(signer)
-		if fetchErr != nil {
-			return nil, fmt.Errorf("verifying PKCS7 certificate chain: embedded=%w; fetch=%w", err, fetchErr)
-		}
-		if err := verifySignerCertChain(signer, p7.Certificates, rootCertPool, intermediateCerts); err != nil {
-			return nil, fmt.Errorf("verifying PKCS7 certificate chain: %w", err)
-		}
+	// Signer SAN was validated above; now it is safe to hit the network.
+	klog.V(2).Infof("Fetching intermediate certificates for signer issuer %q", signer.Issuer)
+	intermediateCerts, err := fetchIntermediates(signer)
+	if err != nil {
+		return nil, fmt.Errorf("fetching intermediate certificates: %w", err)
+	}
+	if err := verifySignerCertChain(signer, p7.Certificates, rootCertPool, intermediateCerts); err != nil {
+		return nil, fmt.Errorf("verifying PKCS7 certificate chain: %w", err)
 	}
+	klog.V(2).Infof("PKCS7 certificate chain verified for signer issuer %q", signer.Issuer)
 
 	return parseAndValidateAttestedDocumentContent(p7.Content, body)
 }
@@ -211,24 +209,29 @@ func parseAndValidatePKCS7Signer(signature string) (*pkcs7.PKCS7, *x509.Certific
 	if err != nil {
 		return nil, nil, fmt.Errorf("decoding PKCS7 signature: %w", err)
 	}
+	klog.V(4).Infof("Decoded PKCS7 signature (%d bytes)", len(sigBytes))
 
 	p7, err := pkcs7.Parse(sigBytes)
 	if err != nil {
 		return nil, nil, fmt.Errorf("parsing PKCS7 signature: %w", err)
 	}
+	klog.V(8).Infof("Parsed PKCS7 structure with %d embedded certificate(s)", len(p7.Certificates))
 
 	// Verify the PKCS7 signature against the embedded leaf certificate.
 	if err := p7.Verify(); err != nil {
 		return nil, nil, fmt.Errorf("verifying PKCS7 signature: %w", err)
 	}
+	klog.V(4).Infof("PKCS7 self-signature verified")
 
 	signer := p7.GetOnlySigner()
 	if signer == nil {
 		return nil, nil, fmt.Errorf("getting PKCS7 signer certificate")
 	}
+	klog.V(8).Infof("PKCS7 signer certificate: subject=%q issuer=%q SANs=%v", signer.Subject, signer.Issuer, signer.DNSNames)
 	if err := validateAzureMetadataSignerSAN(signer); err != nil {
 		return nil, nil, fmt.Errorf("validating PKCS7 signer SAN: %w", err)
 	}
+	klog.V(4).Infof("PKCS7 signer SAN validated as Azure metadata endpoint")
 
 	return p7, signer, nil
 }
@@ -248,11 +251,14 @@ func parseAndValidateAttestedDocumentContent(content []byte, body []byte) (*atte
 	if err := json.Unmarshal(content, &data); err != nil {
 		return nil, fmt.Errorf("unmarshalling attested data: %w", err)
 	}
+	klog.V(4).Infof("Attested document content: vmId=%q subscriptionId=%q nonce=%q createdOn=%q expiresOn=%q", data.VMId, data.SubscriptionId, data.Nonce, data.TimeStamp.CreatedOn, data.TimeStamp.ExpiresOn)
 
 	// Verify the nonce matches the request body hash (replay protection).
-	if data.Nonce != nonceForBody(body) {
-		return nil, fmt.Errorf("attested document nonce mismatch")
+	expectedNonce := nonceForBody(body)
+	if data.Nonce != expectedNonce {
+		return nil, fmt.Errorf("attested document nonce mismatch: got=%q expected=%q", data.Nonce, expectedNonce)
 	}
+	klog.V(4).Infof("Attested document nonce verified")
 
 	// Verify the attested document has not expired.
 	if data.TimeStamp.ExpiresOn != "" {
@@ -263,6 +269,7 @@ func parseAndValidateAttestedDocumentContent(content []byte, body []byte) (*atte
 		if time.Now().After(expiresOn) {
 			return nil, fmt.Errorf("attested document expired at %s", data.TimeStamp.ExpiresOn)
 		}
+		klog.V(4).Infof("Attested document not expired (expiresOn=%s)", expiresOn.Format(time.RFC3339))
 	}
 
 	return &data, nil
@@ -319,12 +326,14 @@ func intermediateCertPoolWithCaches(signer *x509.Certificate, fetch func(*x509.C
 	// Positive cache wins over negative: a successful later fetch overwrites
 	// any stale negative entry, which expires on its own shorter TTL.
 	if obj, ok, _ := positive.GetByKey(keyStr); ok {
+		klog.V(4).Infof("Intermediate certificate cache hit (positive) for signer issuer %q", signer.Issuer)
 		return obj.(*intermediateCertCacheEntry).pool, nil
 	}
 	if _, ok, _ := negative.GetByKey(keyStr); ok {
-		return nil, fmt.Errorf("intermediate certificate fetch recently failed for signer issuer (cached)")
+		return nil, fmt.Errorf("intermediate certificate fetch recently failed for signer issuer %q (cached)", signer.Issuer)
 	}
 
+	klog.V(2).Infof("Intermediate certificate cache miss for signer issuer %q; fetching from Microsoft PKI", signer.Issuer)
 	pool, fetchErr := fetch(signer)
 	entry.pool = pool
 	if fetchErr != nil {
@@ -373,19 +382,23 @@ func fetchIntermediateCertsFromBaseURL(client *http.Client, baseURL string, sign
 	pool := x509.NewCertPool()
 	matched := 0
 	for _, url := range urls {
+		klog.V(4).Infof("Fetching intermediate certificate from %s", url)
 		cert, err := fetchCertificate(client, url)
 		if err != nil {
 			return nil, err
 		}
 		if err := validateFetchedIntermediateForSigner(signer, cert); err != nil {
+			klog.V(4).Infof("Fetched certificate from %s did not match signer issuer: %v", url, err)
 			continue
 		}
+		klog.V(4).Infof("Fetched intermediate certificate from %s matched signer issuer (subject=%q)", url, cert.Subject)
 		pool.AddCert(cert)
 		matched++
 	}
 	if matched == 0 {
-		return nil, fmt.Errorf("no fetched intermediate certificates matched signer issuer")
+		return nil, fmt.Errorf("no fetched intermediate certificates matched signer issuer %q", signer.Issuer)
 	}
+	klog.V(2).Infof("Fetched %d intermediate certificate(s) matching signer issuer %q from %d candidate URL(s)", matched, signer.Issuer, len(urls))
 
 	return pool, nil
 }

upup/pkg/fi/cloudup/azure/attest_test.go

@@ -30,7 +30,6 @@ import (
 	"math/big"
 	"net/http"
 	"slices"
-	"strings"
 	"testing"
 	"time"
 
@@ -777,7 +776,7 @@ func TestVerifyAttestedDocumentWithCertPools(t *testing.T) {
 // TestVerifyAttestedDocumentWithRootAndFetcher_SkipsFetchWhenEmbeddedChainSuffices
 // verifies that the verifier accepts an attestation using only embedded PKCS7
 // certificates and does not consult Microsoft PKI in that case.
-func TestVerifyAttestedDocumentWithRootAndFetcher_SkipsFetchWhenEmbeddedChainSuffices(t *testing.T) {
+func TestVerifyAttestedDocumentWithRootAndFetcher_AlwaysFetchesIntermediates(t *testing.T) {
 	rootCert, intermediateCert, leafCert, leafKey := testPKIChain(t)
 
 	body := []byte("test-body")
@@ -793,6 +792,7 @@ func TestVerifyAttestedDocumentWithRootAndFetcher_SkipsFetchWhenEmbeddedChainSuf
 	if err != nil {
 		t.Fatalf("marshalling attested data: %v", err)
 	}
+	// Include the intermediate in the PKCS7 to confirm the fetcher is still called.
 	sig := base64.StdEncoding.EncodeToString(createTestPKCS7(t, content, leafCert, leafKey, intermediateCert))
 
 	rootPool := x509.NewCertPool()
@@ -801,16 +801,18 @@ func TestVerifyAttestedDocumentWithRootAndFetcher_SkipsFetchWhenEmbeddedChainSuf
 	fetchCalls := 0
 	result, err := verifyAttestedDocumentWithRootAndFetcher(sig, body, rootPool, func(*x509.Certificate) (*x509.CertPool, error) {
 		fetchCalls++
-		return nil, fmt.Errorf("unexpected fetch")
+		pool := x509.NewCertPool()
+		pool.AddCert(intermediateCert)
+		return pool, nil
 	})
 	if err != nil {
 		t.Fatalf("unexpected verification error: %v", err)
 	}
 	if result.VMId != "test-vm-id" {
 		t.Fatalf("expected vmId %q, got %q", "test-vm-id", result.VMId)
 	}
-	if fetchCalls != 0 {
-		t.Fatalf("fetch call count mismatch: got %d, want 0", fetchCalls)
+	if fetchCalls != 1 {
+		t.Fatalf("fetch call count mismatch: got %d, want 1", fetchCalls)
 	}
 }
 
@@ -856,10 +858,9 @@ func TestVerifyAttestedDocumentWithRootAndFetcher_FetchesMissingIntermediate(t *
 	}
 }
 
-// TestVerifyAttestedDocumentWithRootAndFetcher_CombinesEmbeddedAndFetchErrors
-// verifies that when the embedded chain fails AND the fetcher also fails, the
-// returned error wraps both so callers can inspect either cause.
-func TestVerifyAttestedDocumentWithRootAndFetcher_CombinesEmbeddedAndFetchErrors(t *testing.T) {
+// TestVerifyAttestedDocumentWithRootAndFetcher_PropagatesFetchError verifies
+// that when the fetcher fails, the error is propagated to the caller.
+func TestVerifyAttestedDocumentWithRootAndFetcher_PropagatesFetchError(t *testing.T) {
 	rootCert, _, leafCert, leafKey := testPKIChain(t)
 
 	body := []byte("test-body")
@@ -884,14 +885,11 @@ func TestVerifyAttestedDocumentWithRootAndFetcher_CombinesEmbeddedAndFetchErrors
 		return nil, fetchErr
 	})
 	if err == nil {
-		t.Fatal("expected error when both embedded chain and fetch fail")
+		t.Fatal("expected error when fetch fails")
 	}
 	if !errors.Is(err, fetchErr) {
 		t.Errorf("expected wrapped fetchErr in error tree, got: %v", err)
 	}
-	if !strings.Contains(err.Error(), "embedded=") || !strings.Contains(err.Error(), "fetch=") {
-		t.Errorf("expected combined error message to mention both causes, got: %v", err)
-	}
 }
 
 // TestParseAndValidateAttestedDocumentContent_AcceptsMicrosoftFormat verifies

upup/pkg/fi/cloudup/azure/authenticator.go

@@ -19,6 +19,7 @@ package azure
 import (
 	"fmt"
 
+	"k8s.io/klog/v2"
 	"k8s.io/kops/pkg/bootstrap"
 )
 
@@ -39,6 +40,8 @@ func NewAzureAuthenticator() (bootstrap.Authenticator, error) {
 // CreateToken fetches the local VM identity from IMDS and returns a bootstrap
 // token containing the resource ID and signed attested document.
 func (h *azureAuthenticator) CreateToken(body []byte) (string, error) {
+	klog.V(2).Infof("Azure authenticator creating bootstrap token")
+
 	// Query IMDS for the VM's resource ID.
 	metadata, err := QueryComputeInstanceMetadata()
 	if err != nil {
@@ -47,15 +50,19 @@ func (h *azureAuthenticator) CreateToken(body []byte) (string, error) {
 	if metadata == nil || metadata.ResourceID == "" {
 		return "", fmt.Errorf("missing resource ID")
 	}
+	klog.V(4).Infof("Azure authenticator obtained resource ID %q", metadata.ResourceID)
 
 	// Query IMDS for a PKCS7-signed attested document containing the nonce.
-	doc, err := queryIMDSAttestedDocument(nonceForBody(body))
+	nonce := nonceForBody(body)
+	klog.V(4).Infof("Azure authenticator requesting attested document with nonce %q", nonce)
+	doc, err := queryIMDSAttestedDocument(nonce)
 	if err != nil {
 		return "", fmt.Errorf("querying attested document: %w", err)
 	}
 	if doc.Signature == "" {
 		return "", fmt.Errorf("empty attested document signature")
 	}
+	klog.V(2).Infof("Azure authenticator obtained attested document for resource %q", metadata.ResourceID)
 
 	// Token format: "x-azure-id <resourceID> <base64-pkcs7-signature>"
 	return AzureAuthenticationTokenPrefix + metadata.ResourceID + " " + doc.Signature, nil

upup/pkg/fi/cloudup/azure/imds.go

@@ -23,6 +23,8 @@ import (
 	"net/http"
 	"net/url"
 	"time"
+
+	"k8s.io/klog/v2"
 )
 
 const (
@@ -75,6 +77,8 @@ func queryIMDS(path string, params url.Values, result any) error {
 	params.Set("api-version", imdsAPIVersion)
 	req.URL.RawQuery = params.Encode()
 
+	klog.V(4).Infof("Querying Azure IMDS: %s (api-version=%s)", path, imdsAPIVersion)
+
 	resp, err := imdsHTTPClient.Do(req)
 	if err != nil {
 		return fmt.Errorf("querying IMDS %s: %w", path, err)
@@ -89,6 +93,7 @@ func queryIMDS(path string, params url.Values, result any) error {
 	if err != nil {
 		return fmt.Errorf("reading IMDS response: %w", err)
 	}
+	klog.V(8).Infof("Azure IMDS response for %s: %d bytes", path, len(body))
 
 	if err := json.Unmarshal(body, result); err != nil {
 		return fmt.Errorf("unmarshalling IMDS response: %w", err)

upup/pkg/fi/cloudup/azure/verifier.go

@@ -28,6 +28,7 @@ import (
 	"github.com/Azure/azure-sdk-for-go/sdk/azidentity"
 	compute "github.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute"
 	network "github.com/Azure/azure-sdk-for-go/sdk/resourcemanager/network/armnetwork"
+	"k8s.io/klog/v2"
 	"k8s.io/kops/pkg/bootstrap"
 	"k8s.io/kops/pkg/wellknownports"
 )
@@ -82,29 +83,35 @@ func (a azureVerifier) VerifyToken(ctx context.Context, rawRequest *http.Request
 	resourceID := v[0]
 	signature := v[1]
 
+	klog.V(2).Infof("Azure verifier processing token for resource %q", resourceID)
+
 	// Parse the resource ID early to reject malformed tokens before expensive crypto.
 	res, err := arm.ParseResourceID(resourceID)
 	if err != nil {
 		return nil, fmt.Errorf("parsing resource ID: %w", err)
 	}
+	klog.V(4).Infof("Azure verifier parsed resource ID: type=%q subscription=%q resourceGroup=%q name=%q", res.ResourceType, res.SubscriptionID, res.ResourceGroupName, res.Name)
 
 	// Reject resource IDs outside the verifier's own subscription / resource
 	// group. The Azure API lookup below is already scoped to kops-controller's
 	// subscription and resource group, so any claim that names a different
 	// location cannot describe a cluster VM. Failing here avoids a wasted
 	// Azure API call and makes the scope explicit instead of implicit.
 	if !strings.EqualFold(res.SubscriptionID, a.client.subscriptionID) {
-		return nil, fmt.Errorf("resource ID subscription %q does not match verifier subscription", res.SubscriptionID)
+		return nil, fmt.Errorf("resource ID subscription %q does not match verifier subscription %q", res.SubscriptionID, a.client.subscriptionID)
 	}
 	if !strings.EqualFold(res.ResourceGroupName, a.client.resourceGroup) {
-		return nil, fmt.Errorf("resource ID resource group %q does not match verifier resource group", res.ResourceGroupName)
+		return nil, fmt.Errorf("resource ID resource group %q does not match verifier resource group %q", res.ResourceGroupName, a.client.resourceGroup)
 	}
+	klog.V(4).Infof("Azure verifier confirmed resource ID belongs to subscription %q resource group %q", a.client.subscriptionID, a.client.resourceGroup)
 
 	// Verify the PKCS7 attested document: signature, certificate chain, nonce, and expiration.
+	klog.V(2).Infof("Azure verifier verifying attested document for resource %q", resourceID)
 	data, err := verifyAttestedDocument(signature, body)
 	if err != nil {
 		return nil, err
 	}
+	klog.V(2).Infof("Azure verifier attested document verified: vmId=%q subscriptionId=%q", data.VMId, data.SubscriptionId)
 
 	// Look up the VM or VMSS VM via the Azure API using the resource ID,
 	// cross-verify the attested vmId, and extract node identity.
@@ -114,6 +121,7 @@ func (a azureVerifier) VerifyToken(ctx context.Context, rawRequest *http.Request
 	switch res.ResourceType.String() {
 	case "Microsoft.Compute/virtualMachines":
 		vmName := res.Name
+		klog.V(2).Infof("Azure verifier looking up VM %q via Azure API", vmName)
 
 		// Fetch the VM from the Azure API.
 		vm, err := a.client.vmsClient.Get(ctx, a.client.resourceGroup, vmName, nil)
@@ -126,6 +134,7 @@ func (a azureVerifier) VerifyToken(ctx context.Context, rawRequest *http.Request
 
 		// Cross-verify: the vmId from the cryptographically signed attested document
 		// must match the vmId from the Azure API for the claimed resource ID.
+		klog.V(4).Infof("Azure verifier cross-verifying vmId: attested=%q api=%q", data.VMId, *vm.Properties.VMID)
 		if data.VMId != *vm.Properties.VMID {
 			return nil, fmt.Errorf("attested vmId %q does not match VM %q (API vmId %q)", data.VMId, vmName, *vm.Properties.VMID)
 		}
@@ -140,6 +149,7 @@ func (a azureVerifier) VerifyToken(ctx context.Context, rawRequest *http.Request
 		} else {
 			return nil, fmt.Errorf("determining IG name for VM %q", vmName)
 		}
+		klog.V(4).Infof("Azure verifier VM %q identity: node=%q instanceGroup=%q", vmName, nodeName, igName)
 
 		// Collect private IP addresses from the VM's network interface.
 		ni, err := a.client.nisClient.Get(ctx, a.client.resourceGroup, nodeName, nil)
@@ -157,6 +167,7 @@ func (a azureVerifier) VerifyToken(ctx context.Context, rawRequest *http.Request
 	case "Microsoft.Compute/virtualMachineScaleSets/virtualMachines":
 		vmssName := res.Parent.Name
 		vmssIndex := res.Name
+		klog.V(2).Infof("Azure verifier looking up VMSS VM %q #%s via Azure API", vmssName, vmssIndex)
 
 		// Verify the VMSS belongs to this cluster.
 		if !strings.HasSuffix(vmssName, "."+a.clusterName) {
@@ -174,6 +185,7 @@ func (a azureVerifier) VerifyToken(ctx context.Context, rawRequest *http.Request
 
 		// Cross-verify: the vmId from the cryptographically signed attested document
 		// must match the vmId from the Azure API for the claimed resource ID.
+		klog.V(4).Infof("Azure verifier cross-verifying vmId: attested=%q api=%q", data.VMId, *vm.Properties.VMID)
 		if data.VMId != *vm.Properties.VMID {
 			return nil, fmt.Errorf("attested vmId %q does not match VMSS %q VM #%s (API vmId %q)", data.VMId, vmssName, vmssIndex, *vm.Properties.VMID)
 		}
@@ -188,6 +200,7 @@ func (a azureVerifier) VerifyToken(ctx context.Context, rawRequest *http.Request
 		} else {
 			return nil, fmt.Errorf("determining IG name for VM %q", vmssName)
 		}
+		klog.V(4).Infof("Azure verifier VMSS VM %q #%s identity: node=%q instanceGroup=%q", vmssName, vmssIndex, nodeName, igName)
 
 		// Collect private IP addresses from the VMSS VM's network interface.
 		ni, err := a.client.nisClient.GetVirtualMachineScaleSetNetworkInterface(ctx, a.client.resourceGroup, vmssName, vmssIndex, vmssName, nil)
@@ -221,6 +234,7 @@ func (a azureVerifier) VerifyToken(ctx context.Context, rawRequest *http.Request
 		ChallengeEndpoint: challengeEndpoints[0],
 	}
 
+	klog.V(2).Infof("Azure verifier verified node %q in instance group %q with %d address(es)", nodeName, igName, len(addrs))
 	return result, nil
 }
 
@@ -246,6 +260,7 @@ func newVerifierClient() (*client, error) {
 	if metadata.SubscriptionID == "" {
 		return nil, fmt.Errorf("empty subscription ID")
 	}
+	klog.V(4).Infof("Azure verifier client using subscription %q resource group %q", metadata.SubscriptionID, metadata.ResourceGroupName)
 
 	cred, err := azidentity.NewDefaultAzureCredential(nil)
 	if err != nil {