Add explicit opt-in for sensitive NFC/OCR debug logging

.github/workflows/ci.yml

@@ -29,6 +29,7 @@ jobs:
           GOWORK=off go test -race \
             -covermode=atomic \
             -coverprofile=coverage.out \
+            ./cmd/server/... \
             ./internal/apiv1/... \
             ./internal/auditlog/... \
             ./internal/config/... \

Makefile

@@ -23,6 +23,7 @@ GOTEST := GOWORK=off go test -v -race
 # covdata tool (Go ≥ 1.20 multi-package coverage merge) which is not present in
 # every toolchain installation. Limiting to tested packages avoids the error.
 TESTPKGS := \
+	./cmd/server/... \
 	./internal/apiv1/... \
 	./internal/auditlog/... \
 	./internal/config/... \

PRIVACY.md

@@ -60,6 +60,19 @@ technical and organisational measures (TOMs), and considerations relevant to GDP
 | Tenant ID | Operational audit | Yes |
 | Document type (on policy rejection) | Debug logging | At `Debug` level only |
 
+### 2.4 Development-only sensitive debug logging
+
+By default, including at `logging.level: debug`, document identity data is not logged.
+The explicit opt-in `logging.include_pii: true` (`LOG_INCLUDE_PII=true`) permits parsed
+NFC/OCR document fields, including names, dates, document numbers and MRZ lines, to be
+logged **only at Debug level**. It emits a clear warning through the configured logger
+during startup, subject to the configured log level. **Never enable this in production**;
+use it only in isolated test/development environments, preferably with synthetic identities.
+Portraits, raw chip data, FaceMaps and request/response bodies remain excluded.
+This exception applies to document debug diagnostics, not request middleware or audit logs.
+The resulting logs persist in the operator's log sink, outside the in-memory TTL and
+zeroing guarantees: restrict access and retention, and delete them after debugging.
+
 ---
 
 ## 3. Data Flow Diagram
@@ -123,6 +136,7 @@ technical and organisational measures (TOMs), and considerations relevant to GDP
 | Liveness verdict of a `/process-request` session (a boolean, keyed by tenant and `externalDatabaseRefID`) | Process RAM (`session.Manager.proofs`) | `session.liveness_proof_ttl` (default **15 min**) | Deleted on use at the session's final result; TTL eviction |
 | Signed credential | Process RAM (`session.Manager.offers`) | `session.offer_ttl` (default **5 min**) | Deleted atomically on first `GET /v1/offer/:txid`; TTL eviction |
 | Request logs | Log sink (operator-configured) | Operator's log retention policy | No personal data in log fields; see §2.3 |
+| Opt-in document debug logs (development only) | Log sink | Operator-controlled; delete after debugging | May contain document PII only when both Debug logging and `logging.include_pii` are enabled; see §2.4 |
 | Audit log event (`credential_issued`) | Log sink | Operator's log retention policy | Contains: tenant ID, transaction ID, doc type, format, scope, chip trust outcome and reason code, FaceTec `chip_auth_status`, DSC/CSCA certificate fingerprints — **no name, MRZ or biometric data** (the SOD signing time is not logged) |
 
 > **Note:** facetec-api has no database and no persistent storage of any kind. All data described
@@ -247,6 +261,7 @@ The following technical controls are implemented in code:
 | **Explicit zeroing** | `clear(faceMap)` is called on the `[]byte` FaceMap immediately after use (deferred in `SubmitIDScan`), and again by `Manager.Close()` on every in-memory entry at shutdown. |
 | **No body logging** | Gin middleware never logs request or response bodies. The panic-recovery handler is bound to `nil` to prevent biometric data appearing in crash dumps. |
 | **Structured logs scrubbed** | Log fields are explicitly enumerated: method, path, status, latency, IP, user-agent. Biometric scores are absent from Info-level logs. |
+| **Sensitive debug opt-in** | Document identity fields are excluded by default even at Debug level. `logging.include_pii` enables the development-only exception with a startup warning; portraits and raw biometric data remain excluded (§2.4). |
 | **One-time-use sessions** | Liveness entries and credential offers are deleted on first access (`TakeLiveness`, `TakeOffer`). An attacker cannot replay a session ID. |
 | **Rate limiting** | Biometric endpoints are rate-limited per source IP to slow automated bulk enumeration or scraping. |
 | **Short-lived sessions** | Default TTL of 2 min for liveness sessions limits the exposure window if a session ID is intercepted. |

README.md

@@ -84,6 +84,14 @@ by environment variables. The full annotated reference is [configs/config.yaml](
 | `session.offer_ttl` | `SESSION_OFFER_TTL` | `5m` | How long a credential offer is held in memory |
 | `session.liveness_proof_ttl` | `SESSION_LIVENESS_PROOF_TTL` | `15m` | How long FaceTec Server's liveness verdict for a `/process-request` session is held, from its liveness step to its final photo ID match result |
 | `logging.level` | `LOG_LEVEL` | `info` | Log level: `debug`, `info`, `warn`, `error` |
+| `logging.include_pii` | `LOG_INCLUDE_PII` | `false` | Include sensitive NFC/OCR document data only when `logging.level` is `debug`; other levels prevent startup. **Never enable in production**; emits a startup warning when enabled |
+
+Ordinary debug logging does not include document identity data. For isolated test/development
+environments only, set both `LOG_LEVEL=debug` and `LOG_INCLUDE_PII=true` to log parsed
+document fields, including names, dates, document numbers and MRZ lines. Portraits, raw chip
+data and request/response bodies remain excluded. These settings require a process restart;
+SIGHUP reloads tenant settings only. Restrict access to these sensitive logs and delete them
+after debugging; in production, keep `logging.include_pii: false`, including when using debug logs.
 
 Numeric acceptance thresholds are encoded in the SPOCP rule files themselves rather than as
 separate config keys. This keeps deployment policy in one place and allows per-tenant rule sets

cmd/server/main.go

@@ -149,5 +149,12 @@ func buildLogger(cfg *config.Config) (*zap.Logger, error) {
 	default:
 		zapCfg.Level.SetLevel(zap.InfoLevel)
 	}
-	return zapCfg.Build()
+	logger, err := zapCfg.Build()
+	if err != nil {
+		return nil, err
+	}
+	if cfg.Logging.IncludePII {
+		logger.Warn("WARNING: sensitive PII debug logging is enabled (logging.include_pii). NFC/OCR identity data may be written to logs at debug level. NEVER enable this in production.")
+	}
+	return logger, nil
 }

cmd/server/main_test.go

@@ -0,0 +1,47 @@
+package main
+
+import (
+	"os"
+	"strings"
+	"testing"
+
+	"github.com/sirosfoundation/facetec-api/internal/config"
+)
+
+func TestBuildLogger_PIIWarning(t *testing.T) {
+	for _, level := range []string{"debug", "info", "warn", "error"} {
+		for _, include := range []bool{false, true} {
+			t.Run(level+"/"+map[bool]string{false: "default", true: "opt-in"}[include], func(t *testing.T) {
+				stderr, err := os.CreateTemp(t.TempDir(), "stderr")
+				if err != nil {
+					t.Fatal(err)
+				}
+				defer stderr.Close()
+				original := os.Stderr
+				os.Stderr = stderr
+				defer func() { os.Stderr = original }()
+
+				cfg := &config.Config{Logging: config.LoggingConfig{Level: level, IncludePII: include}}
+				log, err := buildLogger(cfg)
+				if err != nil {
+					t.Fatal(err)
+				}
+				_ = log.Sync()
+				output, err := os.ReadFile(stderr.Name())
+				if err != nil {
+					t.Fatal(err)
+				}
+				warningExpected := include && level != "error"
+				if warningExpected {
+					for _, text := range []string{"WARN", "WARNING", "PII", "NFC/OCR", "NEVER enable this in production"} {
+						if !strings.Contains(string(output), text) {
+							t.Errorf("startup warning missing %q: %s", text, output)
+						}
+					}
+				} else if len(output) != 0 {
+					t.Errorf("unexpected startup warning: %s", output)
+				}
+			})
+		}
+	}
+}

configs/config.yaml

@@ -126,6 +126,9 @@ jwt:
 logging:
   # Log level: debug, info, warn, error
   level: "info"
+  # Include sensitive NFC/OCR identity data only at debug level (LOG_INCLUDE_PII).
+  # DEVELOPMENT/TEST ONLY — never enable in production. Emits a startup warning.
+  include_pii: false
 
 # ── Tenant overrides (optional) ───────────────────────────────────────────────
 # When this block is absent, a single "default" tenant is synthesised from the

internal/apiv1/client.go

@@ -171,6 +171,8 @@ func (c *Client) SubmitIDScan(ctx context.Context, livenessSessionID string, idS
 		return "", "", fmt.Errorf("id-scan: tenant context missing from request")
 	}
 
+	c.logDocumentData("id-scan document data", tc.ID, 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 +274,8 @@ func (c *Client) ProcessRequest(ctx context.Context, req *facetec.ProcessRequest
 		return resp, nil
 	}
 
+	c.logDocumentData("process-request document data", tc.ID, 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
@@ -367,6 +371,19 @@ func (c *Client) ProcessRequest(ctx context.Context, req *facetec.ProcessRequest
 	return resp, nil
 }
 
+// logDocumentData is development-only; biometric images are always omitted.
+func (c *Client) logDocumentData(message, tenantID string, doc facetec.DocumentData) {
+	if !c.cfg.Logging.IncludePII {
+		return
+	}
+	if entry := c.log.Check(zap.DebugLevel, message); entry != nil {
+		if n := len(doc.Portrait); n > 0 {
+			doc.Portrait = fmt.Sprintf("[%d bytes omitted]", n)
+		}
+		entry.Write(zap.String("tenant", tenantID), zap.Any("document_data", doc))
+	}
+}
+
 // nfcRejection reports why a scan without an authenticated chip is refused,
 // or rejected=false when the chip was authenticated. The code tells the
 // client what the user can do about it.

internal/apiv1/logging_test.go

@@ -0,0 +1,95 @@
+package apiv1
+
+import (
+	"bytes"
+	"encoding/json"
+	"fmt"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	"github.com/sirosfoundation/facetec-api/internal/facetec"
+	"github.com/sirosfoundation/facetec-api/internal/tenant"
+)
+
+func TestDocumentLogging(t *testing.T) {
+	doc := facetec.DocumentData{
+		GivenName: "SyntheticGivenName", FamilyName: "SyntheticFamilyName",
+		DocumentNumber: "TEST-DOC-123", DateOfBirth: "1980-01-02",
+		DateOfExpiry: "2099-12-31", MRZLine1: "SYNTHETIC-MRZ-LINE",
+		DocumentType: "passport", Portrait: "synthetic-face-image",
+	}
+	docJSON, err := json.Marshal(doc)
+	require.NoError(t, err)
+
+	for _, path := range []string{"id-scan", "process-request"} {
+		for _, tt := range []struct {
+			name    string
+			level   zapcore.Level
+			include bool
+			wantPII bool
+		}{
+			{"debug default", zap.DebugLevel, false, false},
+			{"debug opt-in", zap.DebugLevel, true, true},
+			{"info opt-in", zap.InfoLevel, true, false},
+			{"warn opt-in", zap.WarnLevel, true, false},
+			{"error opt-in", zap.ErrorLevel, true, false},
+		} {
+			t.Run(path+"/"+tt.name, func(t *testing.T) {
+				var c *Client
+				var livenessID string
+				if path == "id-scan" {
+					c, livenessID = newTestClientForIDScan(t, fmt.Sprintf(
+						`{"success":true,"nfcVerified":false,"documentData":%s}`, docJSON))
+					t.Cleanup(c.sessions.Close)
+				} else {
+					c = newTestClientForProcessRequest(t, fmt.Sprintf(
+						`{"idScanResultsSoFar":{"photoIDNextStepEnumInt":4,"matchLevel":7,"documentData":%s}}`, docJSON))
+				}
+				c.cfg.Logging.IncludePII = tt.include
+				var output bytes.Buffer
+				c.log = zap.New(zapcore.NewCore(
+					zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()),
+					zapcore.AddSync(&output), tt.level,
+				))
+				ctx := tenant.WithStdContext(t.Context(), &tenant.Context{ID: "test-tenant"})
+				if path == "id-scan" {
+					_, _, err := c.SubmitIDScan(ctx, livenessID, &facetec.IDScanRequest{})
+					require.Error(t, err, "NFC gate remains enforced")
+				} else {
+					resp, err := c.ProcessRequest(ctx, &facetec.ProcessRequestRequest{RequestBlob: "opaque"})
+					require.NoError(t, err)
+					assert.NotEmpty(t, resp.CredentialIssueErrCode, "liveness gate remains enforced")
+				}
+				logs := output.String()
+				for _, pii := range []string{doc.GivenName, doc.FamilyName, doc.DocumentNumber, doc.DateOfBirth, doc.DateOfExpiry, doc.MRZLine1} {
+					if tt.wantPII {
+						assert.Contains(t, logs, pii)
+					} else {
+						assert.NotContains(t, logs, pii)
+					}
+				}
+				assert.NotContains(t, logs, doc.Portrait, "portraits must never be logged")
+				if tt.wantPII {
+					assert.Contains(t, logs, fmt.Sprintf("[%d bytes omitted]", len(doc.Portrait)))
+				}
+				assert.Equal(t, tt.wantPII, bytes.Contains(output.Bytes(), []byte("document_data")))
+			})
+		}
+	}
+}
+
+func TestLogDocumentData_DoesNotMutateDocument(t *testing.T) {
+	doc := facetec.DocumentData{GivenName: "SyntheticName", Portrait: "synthetic-face-image"}
+	original := doc
+	var output bytes.Buffer
+	c := newTestClientForProcessRequest(t, `{}`)
+	c.cfg.Logging.IncludePII = true
+	c.log = zap.New(zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), zapcore.AddSync(&output), zap.DebugLevel))
+	c.logDocumentData("test document data", "test-tenant", doc)
+	assert.Equal(t, original, doc)
+	assert.NotContains(t, output.String(), doc.Portrait)
+}

internal/config/config.go

@@ -230,6 +230,8 @@ type TrustConfig struct {
 // LoggingConfig controls log output.
 type LoggingConfig struct {
 	Level string `yaml:"level" envconfig:"LOG_LEVEL"`
+	// IncludePII enables sensitive document data at debug level. Never use in production.
+	IncludePII bool `yaml:"include_pii" envconfig:"LOG_INCLUDE_PII"`
 }
 
 // AuditConfig controls persistent IPV session audit logging.
@@ -279,6 +281,9 @@ func Load(path string) (*Config, error) {
 // Validate returns an error if required fields are missing or if the
 // configuration is unsafe for a production deployment.
 func (c *Config) Validate() error {
+	if c.Logging.IncludePII && c.Logging.Level != "debug" {
+		return fmt.Errorf("config: logging.include_pii requires logging.level: debug")
+	}
 	if c.FaceTec.ServerURL == "" {
 		return fmt.Errorf("config: facetec.server_url is required")
 	}

internal/config/config_test.go

@@ -36,6 +36,39 @@ func TestLoad_Defaults(t *testing.T) {
 	if cfg.Server.MaxConcurrentBiometric != 10 {
 		t.Errorf("Server.MaxConcurrentBiometric: got %d, want 10", cfg.Server.MaxConcurrentBiometric)
 	}
+	if cfg.Logging.IncludePII {
+		t.Error("Logging.IncludePII: want false by default")
+	}
+}
+
+func TestLoad_LoggingIncludePII(t *testing.T) {
+	for _, tt := range []struct {
+		name string
+		env  string
+		yaml string
+		want bool
+	}{
+		{"yaml opt-in", "", "true", true},
+		{"env opt-in", "true", "false", true},
+		{"env overrides yaml", "false", "true", false},
+	} {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Setenv("LOG_INCLUDE_PII", tt.env)
+			if tt.env == "" {
+				if err := os.Unsetenv("LOG_INCLUDE_PII"); err != nil {
+					t.Fatal(err)
+				}
+			}
+			path := writeTemp(t, "config.yaml", "logging:\n  level: debug\n  include_pii: "+tt.yaml+"\n")
+			cfg, err := config.Load(path)
+			if err != nil {
+				t.Fatalf("Load: %v", err)
+			}
+			if cfg.Logging.IncludePII != tt.want {
+				t.Errorf("Logging.IncludePII: got %v, want %v", cfg.Logging.IncludePII, tt.want)
+			}
+		})
+	}
 }
 
 // TestLoad_FromFile verifies that values are read from a YAML file.
@@ -152,6 +185,29 @@ func TestValidate_MissingServerURL(t *testing.T) {
 	}
 }
 
+func TestValidate_IncludePIIRequiresDebugLevel(t *testing.T) {
+	for _, level := range []string{"", "info", "warn", "error"} {
+		t.Run(level, func(t *testing.T) {
+			cfg := &config.Config{
+				Logging: config.LoggingConfig{Level: level, IncludePII: true},
+			}
+			if err := cfg.Validate(); err == nil {
+				t.Errorf("expected error when logging.include_pii is enabled with level %q", level)
+			}
+		})
+	}
+
+	cfg := &config.Config{
+		FaceTec: config.FaceTecConfig{ServerURL: "https://x"},
+		Issuer:  config.IssuerConfig{Addr: "x", Scope: "s"},
+		JWT:     config.JWTConfig{Secret: "shared-secret"},
+		Logging: config.LoggingConfig{Level: "debug", IncludePII: true},
+	}
+	if err := cfg.Validate(); err != nil {
+		t.Errorf("unexpected error with debug logging: %v", err)
+	}
+}
+
 func TestValidate_WithoutDeviceKey(t *testing.T) {
 	cfg := &config.Config{
 		FaceTec: config.FaceTecConfig{ServerURL: "https://x"},