Log certificate posture details at debug level

This commit is contained in:
Viktor Liu
2026-10-01 08:45:01 +02:00
parent a230d39aa0
commit 0129b90ae3
11 changed files with 46 additions and 46 deletions
+10 -10
View File
@@ -25,14 +25,14 @@ func Collect(ctx context.Context, store Store, checks []*proto.Checks, peerKey [
func logNoChallenges(checks []*proto.Checks) { func logNoChallenges(checks []*proto.Checks) {
if len(checks) > 0 { if len(checks) > 0 {
log.Infof("certificate posture: %d posture checks received, none carries a certificate challenge", len(checks)) log.Debugf("certificate posture: %d posture checks received, none carries a certificate challenge", len(checks))
} }
} }
// CollectChallenges answers challenges already extracted from the posture checks, so a // CollectChallenges answers challenges already extracted from the posture checks, so a
// caller that ships them across a process boundary reuses the same matching and signing. // caller that ships them across a process boundary reuses the same matching and signing.
func CollectChallenges(ctx context.Context, store Store, challenges []*proto.CertificateChallenge, peerKey []byte) []certposture.Proof { func CollectChallenges(ctx context.Context, store Store, challenges []*proto.CertificateChallenge, peerKey []byte) []certposture.Proof {
log.Infof("certificate posture: answering %d certificate challenges from store %T", len(challenges), store) log.Debugf("certificate posture: answering %d certificate challenges from store %T", len(challenges), store)
candidates, err := store.Candidates(ctx) candidates, err := store.Candidates(ctx)
if err != nil { if err != nil {
@@ -40,10 +40,10 @@ func CollectChallenges(ctx context.Context, store Store, challenges []*proto.Cer
return nil return nil
} }
if len(candidates) == 0 { if len(candidates) == 0 {
log.Info("certificate posture: certificate store holds no candidates, no proof will be sent") log.Debug("certificate posture: certificate store holds no candidates, no proof will be sent")
return nil return nil
} }
log.Infof("certificate posture: store holds %d candidate certificates", len(candidates)) log.Debugf("certificate posture: store holds %d candidate certificates", len(candidates))
now := time.Now() now := time.Now()
proven := make(map[[sha256.Size]byte]struct{}) proven := make(map[[sha256.Size]byte]struct{})
@@ -54,7 +54,7 @@ func CollectChallenges(ctx context.Context, store Store, challenges []*proto.Cer
log.Warnf("skipping certificate challenge with invalid CA certificates: %v", err) log.Warnf("skipping certificate challenge with invalid CA certificates: %v", err)
continue continue
} }
log.Infof("certificate posture: challenge %d accepts %d CA certificates, nonce is %d bytes", i, len(challenge.GetCaCertificates()), len(challenge.GetNonce())) log.Debugf("certificate posture: challenge %d accepts %d CA certificates, nonce is %d bytes", i, len(challenge.GetCaCertificates()), len(challenge.GetNonce()))
matched := false matched := false
for _, candidate := range candidates { for _, candidate := range candidates {
@@ -63,14 +63,14 @@ func CollectChallenges(ctx context.Context, store Store, challenges []*proto.Cer
} }
leaf := candidate.Chain[0] leaf := candidate.Chain[0]
if err := certposture.VerifyChain(candidate.Chain, roots, now); err != nil { if err := certposture.VerifyChain(candidate.Chain, roots, now); err != nil {
log.Infof("certificate posture: challenge %d rejected %q issued by %q, chain of %d: %v", i, leaf.Subject, leaf.Issuer, len(candidate.Chain), err) log.Debugf("certificate posture: challenge %d rejected %q issued by %q, chain of %d: %v", i, leaf.Subject, leaf.Issuer, len(candidate.Chain), err)
continue continue
} }
matched = true matched = true
fingerprint := sha256.Sum256(leaf.Raw) fingerprint := sha256.Sum256(leaf.Raw)
if _, done := proven[fingerprint]; done { if _, done := proven[fingerprint]; done {
log.Infof("certificate posture: challenge %d matched %q, already proven for an earlier challenge", i, leaf.Subject) log.Debugf("certificate posture: challenge %d matched %q, already proven for an earlier challenge", i, leaf.Subject)
break break
} }
proof, err := prove(candidate, challenge.GetNonce(), peerKey) proof, err := prove(candidate, challenge.GetNonce(), peerKey)
@@ -78,16 +78,16 @@ func CollectChallenges(ctx context.Context, store Store, challenges []*proto.Cer
log.Warnf("failed signing certificate proof for %s: %v", leaf.Subject, err) log.Warnf("failed signing certificate proof for %s: %v", leaf.Subject, err)
continue continue
} }
log.Infof("certificate posture: challenge %d proven by %q with %s, signature %d bytes, chain of %d", i, leaf.Subject, proof.SigAlg, len(proof.Signature), len(proof.Chain)) log.Debugf("certificate posture: challenge %d proven by %q with %s, signature %d bytes, chain of %d", i, leaf.Subject, proof.SigAlg, len(proof.Signature), len(proof.Chain))
proven[fingerprint] = struct{}{} proven[fingerprint] = struct{}{}
proofs = append(proofs, proof) proofs = append(proofs, proof)
break break
} }
if !matched { if !matched {
log.Infof("certificate posture: challenge %d matched none of the %d candidates", i, len(candidates)) log.Debugf("certificate posture: challenge %d matched none of the %d candidates", i, len(candidates))
} }
} }
log.Infof("certificate posture: %d challenges produced %d proofs", len(challenges), len(proofs)) log.Debugf("certificate posture: %d challenges produced %d proofs", len(challenges), len(proofs))
return proofs return proofs
} }
+1 -1
View File
@@ -38,7 +38,7 @@ func CollectProofs(ctx context.Context, checks []*proto.Checks, peerKey []byte,
userProofs, err := collectAsConsoleUser(ctx, challenges, peerKey) userProofs, err := collectAsConsoleUser(ctx, challenges, peerKey)
if err != nil { if err != nil {
log.Infof("certificate posture: console user keychain unavailable: %v", err) log.Debugf("certificate posture: console user keychain unavailable: %v", err)
} }
return mergeProofs(proofs, userProofs) return mergeProofs(proofs, userProofs)
} }
+1 -1
View File
@@ -39,7 +39,7 @@ func CollectProofs(ctx context.Context, checks []*proto.Checks, peerKey []byte,
userProofs, err := collectAsDesktopUser(ctx, challenges, peerKey) userProofs, err := collectAsDesktopUser(ctx, challenges, peerKey)
if err != nil { if err != nil {
log.Infof("certificate posture: user certificate store unavailable: %v", err) log.Debugf("certificate posture: user certificate store unavailable: %v", err)
} }
return mergeProofs(proofs, userProofs) return mergeProofs(proofs, userProofs)
} }
@@ -37,21 +37,21 @@ type ConsoleUser struct {
// or attributes the session to root, and neither has a login keychain to offer. // or attributes the session to root, and neither has a login keychain to offer.
func CurrentConsoleUser() (ConsoleUser, bool) { func CurrentConsoleUser() (ConsoleUser, bool) {
if err := loadConsoleUser(); err != nil { if err := loadConsoleUser(); err != nil {
log.Infof("console user lookup unavailable: %v", err) log.Debugf("console user lookup unavailable: %v", err)
return ConsoleUser{}, false return ConsoleUser{}, false
} }
var uid, gid uint32 var uid, gid uint32
name := scDynamicStoreCopyConsoleUser(0, &uid, &gid) name := scDynamicStoreCopyConsoleUser(0, &uid, &gid)
if name == 0 { if name == 0 {
log.Info("no console user is logged in, no login keychain is reachable") log.Debug("no console user is logged in, no login keychain is reachable")
return ConsoleUser{}, false return ConsoleUser{}, false
} }
defer cfRelease(name) defer cfRelease(name)
user := ConsoleUser{Name: cfString(name), UID: uid, GID: gid} user := ConsoleUser{Name: cfString(name), UID: uid, GID: gid}
if !user.hasDesktop() { if !user.hasDesktop() {
log.Infof("console session belongs to %q uid=%d, which is not a desktop login, no login keychain is reachable", user.Name, user.UID) log.Debugf("console session belongs to %q uid=%d, which is not a desktop login, no login keychain is reachable", user.Name, user.UID)
return ConsoleUser{}, false return ConsoleUser{}, false
} }
return user, true return user, true
@@ -46,12 +46,12 @@ func CurrentDesktopUser() (DesktopUser, bool) {
if user, ok := desktopUser(session); ok { if user, ok := desktopUser(session); ok {
return user, true return user, true
} }
log.Infof("console session %d has nobody signed in, looking for an active remote session", session) log.Debugf("console session %d has nobody signed in, looking for an active remote session", session)
} }
sessions, err := activeSessions() sessions, err := activeSessions()
if err != nil { if err != nil {
log.Infof("cannot enumerate terminal sessions: %v", err) log.Debugf("cannot enumerate terminal sessions: %v", err)
return DesktopUser{}, false return DesktopUser{}, false
} }
for _, session := range sessions { for _, session := range sessions {
@@ -60,7 +60,7 @@ func CurrentDesktopUser() (DesktopUser, bool) {
} }
} }
log.Info("no interactive session is signed in, no user certificate store is reachable") log.Debug("no interactive session is signed in, no user certificate store is reachable")
return DesktopUser{}, false return DesktopUser{}, false
} }
@@ -73,7 +73,7 @@ func desktopUser(session uint32) (DesktopUser, bool) {
name, err := tokenAccount(token) name, err := tokenAccount(token)
if err != nil { if err != nil {
log.Infof("session %d token has no readable account: %v", session, err) log.Debugf("session %d token has no readable account: %v", session, err)
if closeErr := token.Close(); closeErr != nil { if closeErr := token.Close(); closeErr != nil {
log.Debugf("failed closing session token: %v", closeErr) log.Debugf("failed closing session token: %v", closeErr)
} }
+1 -1
View File
@@ -57,7 +57,7 @@ func runHelper(ctx context.Context, store Store, in io.Reader, out io.Writer) er
if len(challenges) > 0 { if len(challenges) > 0 {
proofs = CollectChallenges(ctx, store, challenges, req.PeerKey) proofs = CollectChallenges(ctx, store, challenges, req.PeerKey)
} }
log.Infof("certificate posture helper: answering %d challenges with %d proofs", len(challenges), len(proofs)) log.Debugf("certificate posture helper: answering %d challenges with %d proofs", len(challenges), len(proofs))
if err := json.NewEncoder(out).Encode(HelperResponse{Proofs: proofs}); err != nil { if err := json.NewEncoder(out).Encode(HelperResponse{Proofs: proofs}); err != nil {
return fmt.Errorf("encode helper response: %w", err) return fmt.Errorf("encode helper response: %w", err)
+2 -2
View File
@@ -56,8 +56,8 @@ func mergeProofs(device, user []certposture.Proof) []certposture.Proof {
func logUserProof(proof certposture.Proof) { func logUserProof(proof certposture.Proof) {
leaf, err := x509.ParseCertificate(proof.Chain[0]) leaf, err := x509.ParseCertificate(proof.Chain[0])
if err != nil { if err != nil {
log.Infof("certificate posture: user proof carries an unparsable leaf: %v", err) log.Debugf("certificate posture: user proof carries an unparsable leaf: %v", err)
return return
} }
log.Infof("certificate posture: signed-in user proved %q issued by %q", leaf.Subject, leaf.Issuer) log.Debugf("certificate posture: signed-in user proved %q issued by %q", leaf.Subject, leaf.Issuer)
} }
+18 -18
View File
@@ -75,7 +75,7 @@ func (s *KeychainStore) Candidates(_ context.Context) ([]Candidate, error) {
log.Warnf("skipping keychain identity: %v", err) log.Warnf("skipping keychain identity: %v", err)
return false, nil return false, nil
} }
log.Infof("keychain identity: subject=%q issuer=%q serial=%s expires=%s", cert.Subject, cert.Issuer, cert.SerialNumber, cert.NotAfter) log.Debugf("keychain identity: subject=%q issuer=%q serial=%s expires=%s", cert.Subject, cert.Issuer, cert.SerialNumber, cert.NotAfter)
leaves = append(leaves, cert) leaves = append(leaves, cert)
return false, nil return false, nil
}) })
@@ -89,17 +89,17 @@ func (s *KeychainStore) Candidates(_ context.Context) ([]Candidate, error) {
return nil, err return nil, err
} }
if len(leaves) == 0 { if len(leaves) == 0 {
log.Infof("keychain search list holds no identities usable for certificate posture, but %d readable certificates: an identity needs its private key in the same keychain", len(pool)) log.Debugf("keychain search list holds no identities usable for certificate posture, but %d readable certificates: an identity needs its private key in the same keychain", len(pool))
return nil, nil return nil, nil
} }
log.Infof("keychain search list holds %d identities and %d certificates for chain building", len(leaves), len(pool)) log.Debugf("keychain search list holds %d identities and %d certificates for chain building", len(leaves), len(pool))
candidates := make([]Candidate, 0, len(leaves)) candidates := make([]Candidate, 0, len(leaves))
for _, leaf := range leaves { for _, leaf := range leaves {
chain := buildChain(leaf, pool) chain := buildChain(leaf, pool)
log.Infof("keychain candidate %q issued by %q built a chain of %d certificates", leaf.Subject, leaf.Issuer, len(chain)) log.Debugf("keychain candidate %q issued by %q built a chain of %d certificates", leaf.Subject, leaf.Issuer, len(chain))
if len(chain) == 1 && leaf.CheckSignatureFrom(leaf) != nil { if len(chain) == 1 && leaf.CheckSignatureFrom(leaf) != nil {
log.Infof("keychain candidate %q has no issuer in the keychain, its proof carries the leaf alone and only verifies if the challenge supplies %q", leaf.Subject, leaf.Issuer) log.Debugf("keychain candidate %q has no issuer in the keychain, its proof carries the leaf alone and only verifies if the challenge supplies %q", leaf.Subject, leaf.Issuer)
} }
candidates = append(candidates, Candidate{Chain: chain, Signer: &keychainSigner{leaf: leaf}}) candidates = append(candidates, Candidate{Chain: chain, Signer: &keychainSigner{leaf: leaf}})
} }
@@ -121,7 +121,7 @@ func (s *keychainSigner) Sign(_ io.Reader, digest []byte, opts crypto.SignerOpts
if err != nil { if err != nil {
return nil, err return nil, err
} }
log.Infof("signing certificate posture challenge with keychain key of %q", s.leaf.Subject) log.Debugf("signing certificate posture challenge with keychain key of %q", s.leaf.Subject)
algorithm := keychainAlgorithm(scheme) algorithm := keychainAlgorithm(scheme)
var signature []byte var signature []byte
@@ -138,7 +138,7 @@ func (s *keychainSigner) Sign(_ io.Reader, digest []byte, opts crypto.SignerOpts
if signature == nil { if signature == nil {
return nil, errors.New("certificate is no longer in the keychain") return nil, errors.New("certificate is no longer in the keychain")
} }
log.Infof("keychain signed certificate posture challenge for %q, %d bytes", s.leaf.Subject, len(signature)) log.Debugf("keychain signed certificate posture challenge for %q, %d bytes", s.leaf.Subject, len(signature))
return signature, nil return signature, nil
} }
@@ -196,7 +196,7 @@ func keychainCertificates() ([]*x509.Certificate, error) {
unparsable++ unparsable++
return false, nil return false, nil
}) })
log.Infof("keychain holds %d parsable certificates, %d unparsable", len(certs), unparsable) log.Debugf("keychain holds %d parsable certificates, %d unparsable", len(certs), unparsable)
return certs, err return certs, err
} }
@@ -210,16 +210,16 @@ func eachMatching(class uintptr, name string, fn func(item uintptr) (bool, error
switch status := secItemCopyMatching(query, &items); status { switch status := secItemCopyMatching(query, &items); status {
case 0: case 0:
case errSecItemNotFound: case errSecItemNotFound:
log.Infof("keychain %s query returned errSecItemNotFound (%d): the search list holds no item of this class", name, errSecItemNotFound) log.Debugf("keychain %s query returned errSecItemNotFound (%d): the search list holds no item of this class", name, errSecItemNotFound)
return nil return nil
default: default:
log.Infof("keychain %s query returned OSStatus %d", name, status) log.Debugf("keychain %s query returned OSStatus %d", name, status)
return fmt.Errorf("SecItemCopyMatching: %d", status) return fmt.Errorf("SecItemCopyMatching: %d", status)
} }
defer cfRelease(items) defer cfRelease(items)
n := cfArrayGetCount(items) n := cfArrayGetCount(items)
log.Infof("keychain %s query returned %d items", name, n) log.Debugf("keychain %s query returned %d items", name, n)
for i := 0; i < n; i++ { for i := 0; i < n; i++ {
if stop, err := fn(cfArrayGetValueAtIndex(items, i)); stop || err != nil { if stop, err := fn(cfArrayGetValueAtIndex(items, i)); stop || err != nil {
return err return err
@@ -241,10 +241,10 @@ func dataBytes(data uintptr) []byte {
func loadKeychain() error { func loadKeychain() error {
keychainOnce.Do(func() { keychainOnce.Do(func() {
if keychainErr = resolveKeychain(); keychainErr != nil { if keychainErr = resolveKeychain(); keychainErr != nil {
log.Infof("macOS keychain unavailable for certificate posture: %v", keychainErr) log.Debugf("macOS keychain unavailable for certificate posture: %v", keychainErr)
return return
} }
log.Infof("macOS Security framework loaded for certificate posture, running as uid=%d euid=%d", os.Getuid(), os.Geteuid()) log.Debugf("macOS Security framework loaded for certificate posture, running as uid=%d euid=%d", os.Getuid(), os.Geteuid())
logSearchList() logSearchList()
}) })
return keychainErr return keychainErr
@@ -254,21 +254,21 @@ func loadKeychain() error {
// System keychain and System Roots, never a user's login keychain. // System keychain and System Roots, never a user's login keychain.
func logSearchList() { func logSearchList() {
if secKeychainCopySearchList == nil || secKeychainGetPath == nil { if secKeychainCopySearchList == nil || secKeychainGetPath == nil {
log.Info("keychain search list diagnostics unavailable on this macOS version") log.Debug("keychain search list diagnostics unavailable on this macOS version")
return return
} }
var list uintptr var list uintptr
if status := secKeychainCopySearchList(&list); status != 0 { if status := secKeychainCopySearchList(&list); status != 0 {
log.Infof("SecKeychainCopySearchList returned OSStatus %d", status) log.Debugf("SecKeychainCopySearchList returned OSStatus %d", status)
return return
} }
defer cfRelease(list) defer cfRelease(list)
n := cfArrayGetCount(list) n := cfArrayGetCount(list)
log.Infof("keychain search list contains %d keychains", n) log.Debugf("keychain search list contains %d keychains", n)
for i := 0; i < n; i++ { for i := 0; i < n; i++ {
log.Infof("keychain search list[%d]: %s", i, keychainPath(cfArrayGetValueAtIndex(list, i))) log.Debugf("keychain search list[%d]: %s", i, keychainPath(cfArrayGetValueAtIndex(list, i)))
} }
} }
@@ -356,7 +356,7 @@ func resolveKeychain() error {
func resolveOptional(lib uintptr, name string, ptr any) { func resolveOptional(lib uintptr, name string, ptr any) {
symbol, err := purego.Dlsym(lib, name) symbol, err := purego.Dlsym(lib, name)
if err != nil { if err != nil {
log.Infof("keychain diagnostics: %s unavailable: %v", name, err) log.Debugf("keychain diagnostics: %s unavailable: %v", name, err)
return return
} }
purego.RegisterFunc(ptr, symbol) purego.RegisterFunc(ptr, symbol)
+3 -3
View File
@@ -72,7 +72,7 @@ func (s *PKCS11Store) Candidates(_ context.Context) ([]Candidate, error) {
if err != nil { if err != nil {
return nil, err return nil, err
} }
log.Infof("%s holds %d certificates, %d certificate files without a key wait for its keys", s, len(certs), len(fileChains)) log.Debugf("%s holds %d certificates, %d certificate files without a key wait for its keys", s, len(certs), len(fileChains))
pool := make([]*x509.Certificate, 0, len(certs)) pool := make([]*x509.Certificate, 0, len(certs))
for _, cert := range certs { for _, cert := range certs {
@@ -85,7 +85,7 @@ func (s *PKCS11Store) Candidates(_ context.Context) ([]Candidate, error) {
var candidates []Candidate var candidates []Candidate
for _, cert := range certs { for _, cert := range certs {
if _, err := privateKey(session, cert.id); err != nil { if _, err := privateKey(session, cert.id); err != nil {
log.Infof("%s certificate %q has no usable private key: %v", s, cert.cert.Subject, err) log.Debugf("%s certificate %q has no usable private key: %v", s, cert.cert.Subject, err)
continue continue
} }
candidates = append(candidates, s.candidate(cert.cert, cert.id, pool)) candidates = append(candidates, s.candidate(cert.cert, cert.id, pool))
@@ -112,7 +112,7 @@ func (s *PKCS11Store) Candidates(_ context.Context) ([]Candidate, error) {
func (s *PKCS11Store) candidate(leaf *x509.Certificate, id []byte, pool []*x509.Certificate) Candidate { func (s *PKCS11Store) candidate(leaf *x509.Certificate, id []byte, pool []*x509.Certificate) Candidate {
chain := buildChain(leaf, pool) chain := buildChain(leaf, pool)
log.Infof("%s candidate %q issued by %q built a chain of %d certificates", s, leaf.Subject, leaf.Issuer, len(chain)) log.Debugf("%s candidate %q issued by %q built a chain of %d certificates", s, leaf.Subject, leaf.Issuer, len(chain))
return Candidate{Chain: chain, Signer: &pkcs11Signer{store: s, leaf: leaf, id: id}} return Candidate{Chain: chain, Signer: &pkcs11Signer{store: s, leaf: leaf, id: id}}
} }
@@ -78,7 +78,7 @@ func (s *SystemStore) Candidates(_ context.Context) ([]Candidate, error) {
if err != nil { if err != nil {
return nil, err return nil, err
} }
log.Infof("certificate store %s holds %d personal certificates and %d intermediates", s, len(leaves), len(intermediates)) log.Debugf("certificate store %s holds %d personal certificates and %d intermediates", s, len(leaves), len(intermediates))
if len(leaves) == 0 { if len(leaves) == 0 {
return nil, nil return nil, nil
} }
@@ -87,7 +87,7 @@ func (s *SystemStore) Candidates(_ context.Context) ([]Candidate, error) {
candidates := make([]Candidate, 0, len(leaves)) candidates := make([]Candidate, 0, len(leaves))
for _, leaf := range leaves { for _, leaf := range leaves {
chain := buildChain(leaf, pool) chain := buildChain(leaf, pool)
log.Infof("certificate store %s candidate %q issued by %q built a chain of %d certificates", s, leaf.Subject, leaf.Issuer, len(chain)) log.Debugf("certificate store %s candidate %q issued by %q built a chain of %d certificates", s, leaf.Subject, leaf.Issuer, len(chain))
candidates = append(candidates, Candidate{Chain: chain, Signer: &systemStoreSigner{leaf: leaf, location: s.location}}) candidates = append(candidates, Candidate{Chain: chain, Signer: &systemStoreSigner{leaf: leaf, location: s.location}})
} }
return candidates, nil return candidates, nil
+1 -1
View File
@@ -1024,7 +1024,7 @@ func infoToMetaData(info *system.Info) *proto.PeerSystemMeta {
}) })
} }
if len(proofs) > 0 { if len(proofs) > 0 {
log.Infof("peer meta carries %d certificate posture proofs", len(proofs)) log.Debugf("peer meta carries %d certificate posture proofs", len(proofs))
} }
return &proto.PeerSystemMeta{ return &proto.PeerSystemMeta{