[object Object]

← back to Dw Signup Fulfillment

TK-11114: un-swallow George send failures (credential-safe logging)

b7b23da2dda8a2c1d4d03572d933ac202c290e08 · 2026-09-02 10:53:24 -0700 · Steve Abrams

Root cause of the DW signup verify-email outage: the running prod service
authenticates to George with a stale GEORGE_BASIC_AUTH process.env override
(!= the on-host DW-Agents/gmail-agent/.env cred), so every /api/send 401s and
the error was SWALLOWED — email.js#georgePost logged nothing on non-2xx and
verify.js#startVerification returned a bare ok:false.

- email.js: georgePost now always surfaces httpStatus + a short bodyPreview;
  sendEmail logs SEND FAILED (status/error/body) or a success line. Never logs
  the Authorization header, Basic-auth, or send token.
- verify.js: startVerification propagates + logs the George reason/status
  (reason:'send_failed', status, error) so retail-webhook.js records why the
  letter didn't go out. Never logs the verify token URL.
- scripts/tk11114-logging-test.js: proves 401 -> ok:false+reason+status logged,
  200 -> ok:true, and NO credential leak in either path.

No config/auth logic changed here (creds resolve correctly from the on-host
file; the stale runtime override is repaired at the pm2 restart step).

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_017e5hAGNWhTKbcLnkkWg4Wv

Files touched

Diff

commit b7b23da2dda8a2c1d4d03572d933ac202c290e08
Author: Steve Abrams <steve@designerwallcoverings.com>
Date:   Wed Sep 2 10:53:24 2026 -0700

    TK-11114: un-swallow George send failures (credential-safe logging)
    
    Root cause of the DW signup verify-email outage: the running prod service
    authenticates to George with a stale GEORGE_BASIC_AUTH process.env override
    (!= the on-host DW-Agents/gmail-agent/.env cred), so every /api/send 401s and
    the error was SWALLOWED — email.js#georgePost logged nothing on non-2xx and
    verify.js#startVerification returned a bare ok:false.
    
    - email.js: georgePost now always surfaces httpStatus + a short bodyPreview;
      sendEmail logs SEND FAILED (status/error/body) or a success line. Never logs
      the Authorization header, Basic-auth, or send token.
    - verify.js: startVerification propagates + logs the George reason/status
      (reason:'send_failed', status, error) so retail-webhook.js records why the
      letter didn't go out. Never logs the verify token URL.
    - scripts/tk11114-logging-test.js: proves 401 -> ok:false+reason+status logged,
      200 -> ok:true, and NO credential leak in either path.
    
    No config/auth logic changed here (creds resolve correctly from the on-host
    file; the stale runtime override is repaired at the pm2 restart step).
    
    Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
    Claude-Session: https://claude.ai/code/session_017e5hAGNWhTKbcLnkkWg4Wv
---
 lib/email.js                                       | 21 ++++-
 lib/verify.js                                      |  9 +-
 scripts/tk11114-logging-test.js                    | 96 ++++++++++++++++++++++
 verification/tk11114-remediation/ROLLBACK-MAP.md   | 38 +++++++++
 .../before-deployed-vs-local-hashes.txt            |  8 ++
 .../before-george-cred-digests.txt                 | 31 +++++++
 .../tk11114-remediation/before-git-head.txt        |  1 +
 .../tk11114-remediation/before-git-status.txt      |  5 ++
 .../tk11114-remediation/before-health-prod.json    |  1 +
 .../tk11114-remediation/before-webhooks.json       |  1 +
 10 files changed, 209 insertions(+), 2 deletions(-)

diff --git a/lib/email.js b/lib/email.js
index 6b43e4d..b00efa7 100644
--- a/lib/email.js
+++ b/lib/email.js
@@ -33,7 +33,18 @@ function georgePost(payload) {
       },
     }, res => {
       let d = ''; res.on('data', c => d += c);
-      res.on('end', () => { try { resolve({ ok: res.statusCode < 400, status: res.statusCode, ...JSON.parse(d) }); } catch { resolve({ ok: res.statusCode < 400, status: res.statusCode, raw: d.slice(0, 300) }); } });
+      res.on('end', () => {
+        // Always surface the HTTP status + a short body preview so a caller can LOG *why*
+        // a send failed (e.g. 401). George's response body never contains our auth secret.
+        const httpStatus = res.statusCode;
+        const bodyPreview = String(d).slice(0, 300);
+        let parsed = null;
+        try { parsed = JSON.parse(d); } catch { /* George returned non-JSON */ }
+        const base = { ok: httpStatus < 400, status: httpStatus, httpStatus, bodyPreview };
+        resolve(parsed && typeof parsed === 'object'
+          ? { ...base, ...parsed, status: httpStatus, httpStatus, bodyPreview }
+          : base);
+      });
     });
     req.on('error', e => resolve({ ok: false, status: 0, error: e.message }));
     req.setTimeout(15000, () => { req.destroy(); resolve({ ok: false, status: 0, error: 'george timeout' }); });
@@ -74,6 +85,14 @@ async function sendEmail({ to, subject, html, source }) {
     return { ok: true, dryRun: true, to, subject };
   }
   const result = await georgePost(payload);
+  // CREDENTIAL-SAFE failure/success logging — the fix for the swallowed George outage.
+  // Logs ONLY the George HTTP status, its error/body preview, and the operational
+  // recipient/source. NEVER logs the Authorization header, the Basic-auth, or the send token.
+  if (result && result.ok === false) {
+    log(`SEND FAILED via George: to=${to} source=${src} status=${result.status != null ? result.status : '?'} error=${result.error || ''} body=${String(result.bodyPreview || '').replace(/\s+/g, ' ').slice(0, 160)}`);
+  } else {
+    log(`sent via George: to=${to} source=${src} status=${result && result.status != null ? result.status : '?'}`);
+  }
   // Fire-and-forget office copy — a separate message; its failure never affects the real send.
   if (officeCopyActive(src) && to !== OFFICE_COPY_TO) {
     georgePost({
diff --git a/lib/verify.js b/lib/verify.js
index e824a25..aa6f028 100644
--- a/lib/verify.js
+++ b/lib/verify.js
@@ -77,8 +77,15 @@ async function startVerification({ email: to, customerId, firstName }) {
   const first = firstName || (addr.includes('@') ? addr.split('@')[0] : '');
   const tpl = email.verifyEmail({ firstName: first, url, count: config.FREE_SAMPLE_COUNT });
   const mail = await email.sendEmail({ to: addr, subject: tpl.subject, html: tpl.html, source: 'retail-verify' });
+  // CREDENTIAL-SAFE: never let a failed send hide again. Log + PROPAGATE the George reason/
+  // status so retail-webhook.js records *why* the letter didn't go out. Never logs the verify
+  // token (carried in `url`), the auth header, or the George body beyond a short preview.
+  if (mail && mail.ok === false) {
+    console.warn(`[verify] verify-email SEND FAILED to=${addr} status=${mail.status != null ? mail.status : '?'} error=${mail.error || ''} body=${String(mail.bodyPreview || '').replace(/\s+/g, ' ').slice(0, 160)}`);
+    return { ok: false, reason: 'send_failed', status: (mail.status != null ? mail.status : null), error: mail.error || null, sent: { to: addr, subject: tpl.subject, dryRun: mail.dryRun || false } };
+  }
   // verifyUrl carries the bearer token — callers must redact it before logging.
-  return { ok: mail.ok !== false, sent: { to: addr, subject: tpl.subject, dryRun: mail.dryRun || false }, verifyUrl: url };
+  return { ok: true, sent: { to: addr, subject: tpl.subject, dryRun: mail.dryRun || false }, verifyUrl: url };
 }
 
 // Step 2 — apply the tag-gated sample entitlement after a valid click. Idempotent.
diff --git a/scripts/tk11114-logging-test.js b/scripts/tk11114-logging-test.js
new file mode 100644
index 0000000..fe6262b
--- /dev/null
+++ b/scripts/tk11114-logging-test.js
@@ -0,0 +1,96 @@
+'use strict';
+// TK-11114 focused test: prove the un-swallow fix.
+//  - On a George FAILURE (401), verify.startVerification returns ok:false with a REASON
+//    (reason:'send_failed', status, error) AND the [email]/[verify] logs surface the status
+//    — but NEVER leak the Basic-auth password or the send token (credential-safe).
+//  - On George SUCCESS (200), it returns ok:true and logs "sent via George".
+// Self-contained: a stub George on 127.0.0.1 (no network, no real email, no Shopify).
+
+const http = require('http');
+const assert = require('assert');
+
+const SECRET_PASS = 'SUPERSECRETPASS_do_not_log_123';
+const SECRET_TOKEN = 'SENDTOKEN_do_not_log_456';
+
+function withStub(statusCode, body, run) {
+  return new Promise((resolve, reject) => {
+    const srv = http.createServer((req, res) => {
+      let d = ''; req.on('data', c => d += c);
+      req.on('end', () => { res.writeHead(statusCode, { 'Content-Type': 'application/json' }); res.end(JSON.stringify(body)); });
+    });
+    srv.listen(0, '127.0.0.1', async () => {
+      const port = srv.address().port;
+      try { const r = await run(port); srv.close(() => resolve(r)); }
+      catch (e) { srv.close(() => reject(e)); }
+    });
+  });
+}
+
+// Capture console output for the duration of one call.
+function captureConsole(fn) {
+  const lines = [];
+  const origLog = console.log, origWarn = console.warn, origErr = console.error;
+  console.log = (...a) => lines.push(a.join(' '));
+  console.warn = (...a) => lines.push(a.join(' '));
+  console.error = (...a) => lines.push(a.join(' '));
+  return Promise.resolve()
+    .then(fn)
+    .then((v) => { console.log = origLog; console.warn = origWarn; console.error = origErr; return { value: v, out: lines.join('\n') }; })
+    .catch((e) => { console.log = origLog; console.warn = origWarn; console.error = origErr; throw e; });
+}
+
+async function loadVerifyPointedAt(port) {
+  // Set env BEFORE requiring config so it resolves to the stub + a live (DRY_RUN=0) send path.
+  process.env.DRY_RUN = '0';
+  process.env.GEORGE_URL = `http://127.0.0.1:${port}`;
+  process.env.DW_SIGNUP_VERIFY_SECRET = 'tk11114-test-secret';
+  process.env.GEORGE_BASIC_AUTH = `testuser:${SECRET_PASS}`;
+  process.env.GEORGE_EXTERNAL_SEND_TOKEN = SECRET_TOKEN;
+  // Fresh module instances so the env above is read at load.
+  for (const m of ['../lib/config', '../lib/email', '../lib/verify']) delete require.cache[require.resolve(m)];
+  return require('../lib/verify');
+}
+
+async function main() {
+  let failures = 0;
+  const fail = (msg) => { console.error('  FAIL:', msg); failures++; };
+  const pass = (msg) => console.log('  PASS:', msg);
+
+  // ---- Case 1: George 401 (the real bug shape) ----
+  await withStub(401, { ok: false, error: 'unauthorized' }, async (port) => {
+    const { value: res, out } = await captureConsole(async () => {
+      const verify = await loadVerifyPointedAt(port);
+      return verify.startVerification({ email: 'buyer@example.com', customerId: '123', firstName: 'Test' });
+    });
+    try {
+      assert.strictEqual(res.ok, false, 'result.ok should be false on 401'); pass('401 → ok:false');
+      assert.strictEqual(res.reason, 'send_failed', 'reason should be send_failed'); pass('401 → reason:send_failed (propagated, not swallowed)');
+      assert.strictEqual(res.status, 401, 'status should be 401'); pass('401 → status:401 surfaced');
+      assert.ok(/SEND FAILED via George/.test(out), 'email.js must log SEND FAILED'); pass('[email] logged SEND FAILED');
+      assert.ok(/status=401/.test(out), 'log must include status=401'); pass('log includes status=401');
+      assert.ok(/verify-email SEND FAILED/.test(out), 'verify.js must warn'); pass('[verify] logged the failure reason');
+      // CREDENTIAL SAFETY — the secret pass + token must NOT appear anywhere in the logs.
+      assert.ok(!out.includes(SECRET_PASS), 'Basic-auth password must NOT be logged'); pass('no Basic-auth password in logs');
+      assert.ok(!out.includes(SECRET_TOKEN), 'send token must NOT be logged'); pass('no send token in logs');
+      assert.ok(!/verify\?token=/.test(out), 'verify token URL must NOT be logged'); pass('no verify token URL in logs');
+    } catch (e) { fail(e.message); }
+  });
+
+  // ---- Case 2: George 200 (happy path) ----
+  await withStub(200, { ok: true, id: 'msg_1' }, async (port) => {
+    const { value: res, out } = await captureConsole(async () => {
+      const verify = await loadVerifyPointedAt(port);
+      return verify.startVerification({ email: 'buyer@example.com', customerId: '123', firstName: 'Test' });
+    });
+    try {
+      assert.strictEqual(res.ok, true, 'result.ok should be true on 200'); pass('200 → ok:true');
+      assert.ok(/sent via George/.test(out), 'should log a success line'); pass('[email] logged success');
+      assert.ok(!out.includes(SECRET_PASS) && !out.includes(SECRET_TOKEN), 'no secrets on success path'); pass('no secrets in success logs');
+    } catch (e) { fail(e.message); }
+  });
+
+  if (failures) { console.error(`\nTK-11114 logging test: ${failures} FAILURE(S)`); process.exit(1); }
+  console.log('\nTK-11114 logging test: ALL PASS');
+}
+
+main().catch((e) => { console.error('test crashed:', e); process.exit(1); });
diff --git a/verification/tk11114-remediation/ROLLBACK-MAP.md b/verification/tk11114-remediation/ROLLBACK-MAP.md
new file mode 100644
index 0000000..205fdda
--- /dev/null
+++ b/verification/tk11114-remediation/ROLLBACK-MAP.md
@@ -0,0 +1,38 @@
+# TK-11114 — Rollback Map (written BEFORE any mutation)
+
+**Agent:** iterm-tk11114-george-repair · **Finalizer:** /root · delegation_chain `/root → iterm-tk11114-george-repair` (depth 1)
+**Written:** 2026-09-02 (pre-mutation) · **Local git HEAD at capture:** `7c99f88`
+**Store:** designer-laboratory-sandbox.myshopify.com (LIVE prod; legacy misnomer) · Admin API 2024-10
+**Prod service:** dw-signup-fulfillment (Kamatera 45.61.58.125, `/root/Projects/dw-signup-fulfillment`, pm2, PORT 9862, DRY_RUN=0, PUBLIC https://signup.designerwallcoverings.com)
+
+## Confirmed root cause (digests only — see before-george-cred-digests.txt)
+The running prod pm2 process carries a **stale `GEORGE_BASIC_AUTH` process.env override**
+(`len=36 last4=eB6P sha8=bd3d134d`) that mismatches George's current on-host Basic-auth
+(`/root/DW-Agents/gmail-agent/.env` → `len=38 last4=DKJO sha8=29398480`). `config.js#firstEnv`
+prefers `process.env` over the file, so every service→George `/api/send` authenticates with the
+wrong password → **401 → 100% send failure**, and the error is **swallowed**. Secondary drift:
+deployed `lib/email.js` (`5d35165a`) omits `message_class:'transactional'` present at HEAD
+(`68f58a04`) — corrected by the same file sync.
+
+## Mutations this task performs (each with a recorded undo)
+
+| # | Change | Where | Undo |
+|---|---|---|---|
+| 1 | Add credential-safe failure logging to `lib/email.js` + `lib/verify.js` (+ a focused test) | LOCAL working tree, committed | `git revert <fix-sha>` (or `git checkout <prev-sha> -- lib/email.js lib/verify.js`) |
+| 2 | Copy approved `lib/email.js` + `lib/verify.js` to prod, **with timestamped backups** `lib/email.js.tk11114.bak.<ts>` / `lib/verify.js.tk11114.bak.<ts>` on Kamatera | Kamatera `/root/Projects/dw-signup-fulfillment/lib/` | `cp lib/email.js.tk11114.bak.<ts> lib/email.js` (same for verify.js) then restart |
+| 3 | Clear the stale `GEORGE_BASIC_AUTH` process.env override + restart ONLY `dw-signup-fulfillment` (via `--update-env` from a shell WITHOUT `GEORGE_BASIC_AUTH`, so config falls through to the correct on-host DKJO file) | Kamatera pm2 | `pm2 restart dw-signup-fulfillment` returns the service to running; if the override is ever wanted back it is re-exportable (it is NOT — it was the bug). Prior process env recorded in before-george-cred-digests.txt |
+| 4 | ONE controlled R4 test customer, Steve-owned `steve+dwgolive-tk11114-<ts>@designerwallcoverings.com` (fires the already-registered customers/create webhook) + its `verified-sample` tag / `custom.sample_verify_sent` / `custom.sample_verified` metafields | LIVE Shopify store | `DELETE /admin/api/2024-10/customers/<TEST_ID>.json` (hard-deletes customer + its tags/metafields). Test id recorded in `test-customer.json` |
+
+- **No webhook created/deleted** (customers/create already exists since 2026-08-06 → nothing to revert there).
+- **Only `dw-signup-fulfillment` is restarted.** No other pm2 process is touched.
+- **No backfill / list send / other Shopify or dw_unified write / DNS / remote push.**
+
+## Critical-failure policy (brief action #4)
+On ANY critical R4 failure: (a) restore the prod file backups (`.tk11114.bak.<ts>`) and restart
+`dw-signup-fulfillment`; (b) delete the test customer by recorded id; (c) report PARTIAL/BLOCKED
+with evidence. Never leave prod in a half-repaired state silently.
+
+## Gate note
+The prod file copy + pm2 restart are prod writes/exec. If the local Claude Code classifier blocks
+autonomous prod SSH writes, the EXACT commands are drafted for Steve/finalizer to paste (`!`), and
+the tab is orange-dotted. Nothing about the gate is loosened by this delegation.
diff --git a/verification/tk11114-remediation/before-deployed-vs-local-hashes.txt b/verification/tk11114-remediation/before-deployed-vs-local-hashes.txt
new file mode 100644
index 0000000..13da6be
--- /dev/null
+++ b/verification/tk11114-remediation/before-deployed-vs-local-hashes.txt
@@ -0,0 +1,8 @@
+file            deployed(kamatera)  local(mac working-tree)
+lib/email.js  DEPLOYED_SEE_BELOW  local=68f58a044858
+lib/verify.js  DEPLOYED_SEE_BELOW  local=49c88931d9f8
+lib/config.js  DEPLOYED_SEE_BELOW  local=de30b542021e
+deployed hashes (captured read-only 2026-09-02):
+  lib/email.js: 5d35165ad68c   (STALE — omits message_class:'transactional')
+  lib/verify.js: 49c88931d9f8  (== local)
+  lib/config.js: de30b542021e  (== local)
diff --git a/verification/tk11114-remediation/before-george-cred-digests.txt b/verification/tk11114-remediation/before-george-cred-digests.txt
new file mode 100644
index 0000000..8449b8c
--- /dev/null
+++ b/verification/tk11114-remediation/before-george-cred-digests.txt
@@ -0,0 +1,31 @@
+TK-11114 remediation — George credential digests (last4 + sha256[:8] ONLY; no secrets)
+Captured read-only 2026-09-02 by iterm-tk11114-george-repair.
+
+KAMATERA (prod — where the customers/create webhook lands):
+  /root/Projects/george-gmail/.env ............ FILE-MISSING  (cred-precedence disproven)
+  /root/DW-Agents/gmail-agent/.env (authoritative):
+      GEORGE_BASIC_AUTH ........... len=38 last4=DKJO sha8=29398480   <-- CORRECT (direct /api/send => 200)
+      GEORGE_EXTERNAL_SEND_TOKEN .. len=48 last4=3e9e sha8=40da76b8   <-- CORRECT
+  /root/Projects/secrets-manager/.env ......... George keys ABSENT
+  /root/Projects/dw-signup-fulfillment/.env ... George keys ABSENT
+
+KAMATERA RUNTIME (running pm2 process /proc/<pid>/environ) — THE FAULT:
+  GEORGE_BASIC_AUTH (process.env OVERRIDE) .... len=36 last4=eB6P sha8=bd3d134d  <-- STALE/WRONG, != file DKJO
+  GEORGE_EXTERNAL_SEND_TOKEN (process.env) .... len=48 last4=3e9e sha8=40da76b8  <-- matches file (fine)
+  GEORGE_URL/ACCOUNT/FROM ..................... unset (fall to config defaults)
+  DRY_RUN=0  PORT=9862  NODE_ENV=production  PUBLIC_URL=https://signup.designerwallcoverings.com
+
+MAC (dev mirror, non-customer-facing):
+  ~/Projects/george-gmail/.env: GEORGE_EXTERNAL_SEND_TOKEN len=48 last4=53d0 sha8=e324d6e2 ; BASIC_AUTH ABSENT
+  ~/DW-Agents/gmail-agent/.env: FILE-MISSING
+  ~/Projects/secrets-manager/.env: GEORGE_AUTH len=38 last4=DKJO sha8=29398480
+
+ROOT CAUSE (confirmed, digests only):
+  config.js#firstEnv prefers process.env over the on-host file. The running prod process
+  carries a STALE GEORGE_BASIC_AUTH override (eB6P/bd3d134d) that mismatches George's
+  current Basic-auth (DKJO/29398480). Every service->George /api/send authenticates with
+  the wrong Basic-auth => 401 => 100% send failure. The error is SWALLOWED
+  (email.js#georgePost logs nothing on non-2xx; verify.js#startVerification returns bare
+  ok:false). A direct shell /api/send uses the correct DKJO file cred => 200, which is why
+  "direct works, organic fails." The deployed email.js message_class omission is a real but
+  SECONDARY drift (a direct call omitting message_class still => 200).
diff --git a/verification/tk11114-remediation/before-git-head.txt b/verification/tk11114-remediation/before-git-head.txt
new file mode 100644
index 0000000..e6767ca
--- /dev/null
+++ b/verification/tk11114-remediation/before-git-head.txt
@@ -0,0 +1 @@
+7c99f8800b93f1e68f01d9d9909f755aa476ab87
diff --git a/verification/tk11114-remediation/before-git-status.txt b/verification/tk11114-remediation/before-git-status.txt
new file mode 100644
index 0000000..0ec5a63
--- /dev/null
+++ b/verification/tk11114-remediation/before-git-status.txt
@@ -0,0 +1,5 @@
+?? apply-verified-tag.sh
+?? claim-kelly.sh
+?? create-kelly-customer.sh
+?? send-kelly-reply.js
+?? verification/tk11114-remediation/
diff --git a/verification/tk11114-remediation/before-health-prod.json b/verification/tk11114-remediation/before-health-prod.json
new file mode 100644
index 0000000..96f305e
--- /dev/null
+++ b/verification/tk11114-remediation/before-health-prod.json
@@ -0,0 +1 @@
+{"ok":true,"service":"dw-signup-fulfillment","dry_run":false,"captured":"2026-09-02","source":"kamatera :9862/healthz"}
diff --git a/verification/tk11114-remediation/before-webhooks.json b/verification/tk11114-remediation/before-webhooks.json
new file mode 100644
index 0000000..cec4ade
--- /dev/null
+++ b/verification/tk11114-remediation/before-webhooks.json
@@ -0,0 +1 @@
+{"webhooks":[{"id":1490453430323,"address":"https:\/\/signup.designerwallcoverings.com\/webhooks\/customers\/create\/[REDACTED-last4:e9c9]","topic":"customers\/create","created_at":"2026-08-06T16:24:15-07:00","updated_at":"2026-08-06T16:24:15-07:00","format":"json","fields":[],"metafield_namespaces":[],"api_version":"2026-07","private_metafield_namespaces":[],"metafield_identifiers":[]},{"id":1499222474803,"address":"https:\/\/signup.designerwallcoverings.com\/webhooks\/orders-paid","topic":"orders\/paid","created_at":"2026-08-28T07:01:33-07:00","updated_at":"2026-08-28T07:01:33-07:00","format":"json","fields":[],"metafield_namespaces":[],"api_version":"2026-07","private_metafield_namespaces":[],"metafield_identifiers":[]}]}

← 7c99f88 auto-data-snapshot: 2026-09-02T10:48:45 (1 data files) — kel  ·  back to Dw Signup Fulfillment  ·  prevent customer data in George failure logs 9e5aa29 →