Add debug logging for processRequest, IDScan and documentExpiryRejection

internal/apiv1/client.go

@@ -171,6 +171,11 @@ func (c *Client) SubmitIDScan(ctx context.Context, livenessSessionID string, idS
 		return "", "", fmt.Errorf("id-scan: tenant context missing from request")
 	}
 
+	c.log.Debug("id-scan document data",
+		zap.String("tenant", tc.ID),
+		zap.Any("document_data", documentDataForLog(idScanResult.DocumentData)),
+	)
+
 	// Same hard gate as ProcessRequest's nfcRejection check, adapted to this
 	// legacy path's response shape. FaceTec's /match-3d-3d response (decoded
 	// directly into IDScanResult) only carries a plain NFCVerified bool, with
@@ -197,7 +202,7 @@ func (c *Client) SubmitIDScan(ctx context.Context, livenessSessionID string, idS
 		return "", "", rej
 	}
 
-	if code, msg, rejected := documentExpiryRejection(idScanResult.DocumentData, time.Now()); rejected {
+	if code, msg, rejected := documentExpiryRejection(c.log, idScanResult.DocumentData, time.Now()); rejected {
 		c.log.Info("id-scan scan rejected: document expiry",
 			zap.String("tenant", tc.ID),
 			zap.String("doc_type", idScanResult.DocumentData.DocumentType),
@@ -272,6 +277,11 @@ func (c *Client) ProcessRequest(ctx context.Context, req *facetec.ProcessRequest
 		return resp, nil
 	}
 
+	c.log.Debug("process-request document data",
+		zap.String("tenant", tc.ID),
+		zap.Any("document_data", documentDataForLog(scanResult.IDScan.DocumentData)),
+	)
+
 	// Hard gate: nothing is issued unless FaceTec Server proved liveness
 	// earlier in this same session. The final response does not say so
 	// itself; the verdict was recorded from the liveness step, keyed by the
@@ -324,7 +334,7 @@ func (c *Client) ProcessRequest(ctx context.Context, req *facetec.ProcessRequest
 
 	// Hard gate: an expired document, or one whose expiry date could not be
 	// read, is not a basis for a credential.
-	if code, msg, rejected := documentExpiryRejection(scanResult.IDScan.DocumentData, time.Now()); rejected {
+	if code, msg, rejected := documentExpiryRejection(c.log, scanResult.IDScan.DocumentData, time.Now()); rejected {
 		c.log.Info("process-request scan rejected: document expiry",
 			zap.String("tenant", tc.ID),
 			zap.String("doc_type", scanResult.IDScan.DocumentData.DocumentType),
@@ -403,18 +413,59 @@ func livenessProofKey(ctx context.Context, externalDatabaseRefID string) (key st
 	return tenantID + "\x00" + externalDatabaseRefID, true
 }
 
+// documentDataForLog is the diagnostic summary of the OCR result written at
+// debug level. It is an allowlist: only the non-personal document type and
+// per-field presence and length are included, never
+// values (name, number, dates, MRZ, portrait), per PRIVACY.md.
+func documentDataForLog(doc facetec.DocumentData) map[string]any {
+	fields := map[string]string{
+		"given_name":      doc.GivenName,
+		"family_name":     doc.FamilyName,
+		"document_number": doc.DocumentNumber,
+		"date_of_birth":   doc.DateOfBirth,
+		"date_of_expiry":  doc.DateOfExpiry,
+		"nationality":     doc.Nationality,
+		"sex":             doc.Sex,
+		"issuing_country": doc.IssuingCountry,
+		"mrz_line1":       doc.MRZLine1,
+		"mrz_line2":       doc.MRZLine2,
+		"mrz_line3":       doc.MRZLine3,
+		"portrait":        doc.Portrait,
+	}
+	out := map[string]any{"document_type": doc.DocumentType}
+	for name, v := range fields {
+		out[name+"_present"] = v != ""
+		out[name+"_len"] = len(v)
+	}
+	return out
+}
+
 // documentExpiryRejection refuses a document that has expired, or whose
 // expiry date is missing or unreadable. A document is valid through its
 // expiry date; dates are compared in UTC.
-func documentExpiryRejection(doc facetec.DocumentData, now time.Time) (code idverrors.Code, msg string, rejected bool) {
+func documentExpiryRejection(log *zap.Logger, doc facetec.DocumentData, now time.Time) (code idverrors.Code, msg string, rejected bool) {
+	nowUTC := now.UTC()
+	fields := []zap.Field{
+		zap.Int("date_of_expiry_len", len(doc.DateOfExpiry)),
+	}
 	expiry, ok := parseISODate(doc.DateOfExpiry)
+	fields = append(fields, zap.Bool("parsed", ok))
 	if !ok {
-		return idverrors.CodeDocumentUnreadable, "the document's expiry date could not be read", true
+		code, msg, rejected = idverrors.CodeDocumentUnreadable, "the document's expiry date could not be read", true
+	} else {
+		// Valid through the expiry date: the first instant it is expired is
+		// the start of the following UTC day.
+		validThrough := expiry.AddDate(0, 0, 1)
+		fields = append(fields, zap.Int("days_until_expiry", int(validThrough.Sub(nowUTC).Hours()/24)))
+		if !nowUTC.Before(validThrough) {
+			code, msg, rejected = idverrors.CodeDocumentExpired, "the document has expired", true
+		}
 	}
-	if !now.UTC().Before(expiry.AddDate(0, 0, 1)) {
-		return idverrors.CodeDocumentExpired, "the document has expired", true
+	if rejected {
+		fields = append(fields, zap.String("code", string(code)))
 	}
-	return "", "", false
+	log.Debug("document expiry check", append(fields, zap.Bool("rejected", rejected))...)
+	return code, msg, rejected
 }
 
 // RedeemOffer retrieves and atomically removes a credential offer by transaction ID.

internal/apiv1/liveness_expiry_test.go

@@ -3,6 +3,7 @@ package apiv1
 import (
 	"context"
 	"errors"
+	"fmt"
 	"net/http"
 	"net/http/httptest"
 	"sync"
@@ -11,6 +12,7 @@ import (
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
+	"go.uber.org/zap"
 
 	"github.com/sirosfoundation/facetec-api/internal/facetec"
 	"github.com/sirosfoundation/facetec-api/internal/idverrors"
@@ -189,7 +191,7 @@ func TestDocumentExpiryRejection(t *testing.T) {
 		{"04-10-2026", true, idverrors.CodeDocumentUnreadable},
 	}
 	for _, tt := range cases {
-		code, msg, rejected := documentExpiryRejection(facetec.DocumentData{DateOfExpiry: tt.expiry}, now)
+		code, msg, rejected := documentExpiryRejection(zap.NewNop(), facetec.DocumentData{DateOfExpiry: tt.expiry}, now)
 		assert.Equal(t, tt.rejected, rejected, "expiry %q", tt.expiry)
 		assert.Equal(t, tt.code, code, "expiry %q", tt.expiry)
 		if rejected {
@@ -200,12 +202,40 @@ func TestDocumentExpiryRejection(t *testing.T) {
 	// The comparison is in UTC: just after midnight UTC on the day after
 	// expiry, the document has expired, whatever the server's time zone.
 	amsterdam := time.FixedZone("CEST", 2*60*60)
-	_, _, rejected := documentExpiryRejection(facetec.DocumentData{DateOfExpiry: "2026-10-03"}, time.Date(2026, 10, 4, 1, 30, 0, 0, amsterdam))
+	_, _, rejected := documentExpiryRejection(zap.NewNop(), facetec.DocumentData{DateOfExpiry: "2026-10-03"}, time.Date(2026, 10, 4, 1, 30, 0, 0, amsterdam))
 	assert.False(t, rejected, "01:30 CEST on the 4th is still the 3rd in UTC")
-	_, _, rejected = documentExpiryRejection(facetec.DocumentData{DateOfExpiry: "2026-10-03"}, time.Date(2026, 10, 4, 2, 30, 0, 0, amsterdam))
+	_, _, rejected = documentExpiryRejection(zap.NewNop(), facetec.DocumentData{DateOfExpiry: "2026-10-03"}, time.Date(2026, 10, 4, 2, 30, 0, 0, amsterdam))
 	assert.True(t, rejected, "02:30 CEST on the 4th is the 4th in UTC")
 }
 
+func TestDocumentDataForLog(t *testing.T) {
+	doc := facetec.DocumentData{
+		GivenName:      "Alice",
+		FamilyName:     "Liddell",
+		DocumentNumber: "X1234567",
+		DateOfBirth:    "1990-01-02",
+		DateOfExpiry:   "2030-05-06",
+		IssuingCountry: "NLD",
+		DocumentType:   "passport",
+		MRZLine1:       "P<NLDLIDDELL<<ALICE",
+		Portrait:       "face-image",
+	}
+	got := documentDataForLog(doc)
+
+	assert.Equal(t, "passport", got["document_type"])
+	assert.Equal(t, true, got["portrait_present"])
+	assert.Equal(t, 10, got["portrait_len"])
+	assert.Equal(t, true, got["given_name_present"])
+	assert.Equal(t, 5, got["given_name_len"])
+	assert.Equal(t, false, got["mrz_line3_present"])
+	assert.Equal(t, 0, got["mrz_line3_len"])
+
+	logged := fmt.Sprint(got)
+	for _, secret := range []string{"Alice", "Liddell", "X1234567", "1990-01-02", "2030-05-06", "NLD", "P<NLD", "face-image"} {
+		assert.NotContains(t, logged, secret)
+	}
+}
+
 func TestSubmitIDScan_ExpiredDocument_Rejected(t *testing.T) {
 	c, livenessID := newTestClientForIDScan(t, `{
 		"success": true,