diff --git a/internal/apiv1/client.go b/internal/apiv1/client.go index d2ec2e0..d465fd3 100644 --- a/internal/apiv1/client.go +++ b/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. diff --git a/internal/apiv1/liveness_expiry_test.go b/internal/apiv1/liveness_expiry_test.go index 3f3c4db..48bea8d 100644 --- a/internal/apiv1/liveness_expiry_test.go +++ b/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