From e130e7c6b802e78bc73429c95d4160a09c1353e4 Mon Sep 17 00:00:00 2001 From: Didr <9605751+Didr@users.noreply.github.com.> Date: Wed, 7 Oct 2026 11:06:18 +0200 Subject: [PATCH 1/4] feat: debug logging for IDscan and processRequest functions We want more information on what data was actually retrieved from the credential. --- internal/apiv1/client.go | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/internal/apiv1/client.go b/internal/apiv1/client.go index d2ec2e0..55d3615 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 @@ -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 @@ -403,6 +413,15 @@ func livenessProofKey(ctx context.Context, externalDatabaseRefID string) (key st return tenantID + "\x00" + externalDatabaseRefID, true } +// documentDataForLog is the OCR result written at debug level. The portrait +// is a base64 face image, so only its length is included. +func documentDataForLog(doc facetec.DocumentData) facetec.DocumentData { + if n := len(doc.Portrait); n > 0 { + doc.Portrait = fmt.Sprintf("[%d bytes omitted]", n) + } + return doc +} + // 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. From e71c85ad665ada5a95b7f7be9158cd969c35660d Mon Sep 17 00:00:00 2001 From: Didr <9605751+Didr@users.noreply.github.com.> Date: Wed, 7 Oct 2026 11:18:38 +0200 Subject: [PATCH 2/4] feat: add debug logging for document expiry rejection --- internal/apiv1/client.go | 29 +++++++++++++++++++------- internal/apiv1/liveness_expiry_test.go | 7 ++++--- 2 files changed, 26 insertions(+), 10 deletions(-) diff --git a/internal/apiv1/client.go b/internal/apiv1/client.go index 55d3615..3db0408 100644 --- a/internal/apiv1/client.go +++ b/internal/apiv1/client.go @@ -202,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), @@ -334,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), @@ -425,15 +425,30 @@ func documentDataForLog(doc facetec.DocumentData) facetec.DocumentData { // 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.String("date_of_expiry", doc.DateOfExpiry), + zap.Time("now_utc", nowUTC), + } 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.Time("expiry", expiry), zap.Time("valid_through", validThrough)) + 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..ca9a2a7 100644 --- a/internal/apiv1/liveness_expiry_test.go +++ b/internal/apiv1/liveness_expiry_test.go @@ -11,6 +11,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 +190,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,9 +201,9 @@ 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") } From 429571c9745d80eeb6a1318de1ba1d91cca5d947 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 7 Oct 2026 11:26:22 +0000 Subject: [PATCH 3/4] test: cover document data log redaction Co-authored-by: Didr <9605751+Didr@users.noreply.github.com> --- internal/apiv1/liveness_expiry_test.go | 33 ++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/internal/apiv1/liveness_expiry_test.go b/internal/apiv1/liveness_expiry_test.go index ca9a2a7..57db684 100644 --- a/internal/apiv1/liveness_expiry_test.go +++ b/internal/apiv1/liveness_expiry_test.go @@ -207,6 +207,39 @@ func TestDocumentExpiryRejection(t *testing.T) { assert.True(t, rejected, "02:30 CEST on the 4th is the 4th in UTC") } +func TestDocumentDataForLog(t *testing.T) { + cases := []struct { + name string + doc facetec.DocumentData + portrait string + }{ + { + name: "redacts portrait", + doc: facetec.DocumentData{ + GivenName: "Alice", + DocumentNumber: "123", + Portrait: "face-image", + }, + portrait: "[10 bytes omitted]", + }, + { + name: "empty portrait", + doc: facetec.DocumentData{ + GivenName: "Alice", + }, + }, + } + for _, tt := range cases { + t.Run(tt.name, func(t *testing.T) { + original := tt.doc + want := tt.doc + want.Portrait = tt.portrait + assert.Equal(t, want, documentDataForLog(tt.doc)) + assert.Equal(t, original, tt.doc, "input remains unchanged") + }) + } +} + func TestSubmitIDScan_ExpiredDocument_Rejected(t *testing.T) { c, livenessID := newTestClientForIDScan(t, `{ "success": true, From 33c27b891597a4442dc149743d5bfdb7bdee7353 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 12 Oct 2026 14:33:52 +0000 Subject: [PATCH 4/4] fix: log only allowlisted document diagnostics, no personal data Co-authored-by: Didr <9605751+Didr@users.noreply.github.com> --- internal/apiv1/client.go | 37 +++++++++++++----- internal/apiv1/liveness_expiry_test.go | 52 ++++++++++++-------------- 2 files changed, 51 insertions(+), 38 deletions(-) diff --git a/internal/apiv1/client.go b/internal/apiv1/client.go index 3db0408..d465fd3 100644 --- a/internal/apiv1/client.go +++ b/internal/apiv1/client.go @@ -413,13 +413,31 @@ func livenessProofKey(ctx context.Context, externalDatabaseRefID string) (key st return tenantID + "\x00" + externalDatabaseRefID, true } -// documentDataForLog is the OCR result written at debug level. The portrait -// is a base64 face image, so only its length is included. -func documentDataForLog(doc facetec.DocumentData) facetec.DocumentData { - if n := len(doc.Portrait); n > 0 { - doc.Portrait = fmt.Sprintf("[%d bytes omitted]", n) - } - return doc +// 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 @@ -428,8 +446,7 @@ func documentDataForLog(doc facetec.DocumentData) facetec.DocumentData { 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.String("date_of_expiry", doc.DateOfExpiry), - zap.Time("now_utc", nowUTC), + zap.Int("date_of_expiry_len", len(doc.DateOfExpiry)), } expiry, ok := parseISODate(doc.DateOfExpiry) fields = append(fields, zap.Bool("parsed", ok)) @@ -439,7 +456,7 @@ func documentExpiryRejection(log *zap.Logger, doc facetec.DocumentData, now time // 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.Time("expiry", expiry), zap.Time("valid_through", validThrough)) + 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 } diff --git a/internal/apiv1/liveness_expiry_test.go b/internal/apiv1/liveness_expiry_test.go index 57db684..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" @@ -208,35 +209,30 @@ func TestDocumentExpiryRejection(t *testing.T) { } func TestDocumentDataForLog(t *testing.T) { - cases := []struct { - name string - doc facetec.DocumentData - portrait string - }{ - { - name: "redacts portrait", - doc: facetec.DocumentData{ - GivenName: "Alice", - DocumentNumber: "123", - Portrait: "face-image", - }, - portrait: "[10 bytes omitted]", - }, - { - name: "empty portrait", - doc: facetec.DocumentData{ - GivenName: "Alice", - }, - }, + doc := facetec.DocumentData{ + GivenName: "Alice", + FamilyName: "Liddell", + DocumentNumber: "X1234567", + DateOfBirth: "1990-01-02", + DateOfExpiry: "2030-05-06", + IssuingCountry: "NLD", + DocumentType: "passport", + MRZLine1: "P