fix(observability,webhooks,i18n): timestamped logs, dedupe webhook retries, default non-de locales to English

- New custom server.js (replaces react-router-serve): ISO timestamps on
  all console.* output and on access logs, and skip successful /healthz
  polls so real traffic stays visible.
- New ProcessedWebhook table + dedupe helper keyed on
  X-Shopify-Webhook-Id; stops Shopify retries from triggering a second
  invoice email when the original delivery exceeded the 5s ack timeout.
- orders/create + orders/fulfilled now respond 200 immediately and run
  the PDF/email work in the background so we stay under that timeout.
- pickLanguage(): non-German locales (it, fr, es, ...) now default to
  English instead of falling back to German. Empty/unknown still maps to
  'de' so the per-shop defaultLanguage chain keeps working.
- Tests for pickLanguage and dedupe via node --test + tsx.
This commit is contained in:
Gerhard Scheikl
2026-05-15 11:02:17 +02:00
parent 274ccfbc01
commit dde53319e5
12 changed files with 361 additions and 29 deletions
+25 -12
View File
@@ -5,6 +5,8 @@ import {
generateAndEmailInvoice,
isManualPaymentOrder,
} from "../services/invoice/automations.server";
import { isDuplicateWebhook } from "../services/webhooks/dedupe.server";
import { runWebhookInBackground } from "../services/webhooks/background.server";
/**
* orders/create — Automation 1: when a wire-transfer (manual-payment-gateway)
@@ -16,31 +18,42 @@ export const action = async ({ request }: ActionFunctionArgs) => {
const { shop, topic, payload, session, admin } = await authenticate.webhook(request);
console.log(`Received ${topic} webhook for ${shop}`);
if (!session || !admin) return new Response();
// Drop Shopify retries we've already processed (prevents the duplicate
// invoice email we saw when the first delivery exceeded Shopify's 5s ack
// timeout — the work still completed, but Shopify resent the webhook).
if (await isDuplicateWebhook(request, shop, topic)) return new Response();
const settings = await db.shopSettings.findUnique({ where: { shopDomain: shop } });
if (!settings?.autoEmailOnWireTransferPlaced) return new Response();
if (!session || !admin) return new Response();
const orderId = payload?.id;
if (orderId == null) return new Response();
const orderGid = `gid://shopify/Order/${String(orderId).replace(/^.*\//, "")}`;
const isManual = await isManualPaymentOrder(admin, orderGid);
if (!isManual) return new Response();
const customerLocale =
typeof payload?.customer_locale === "string" ? payload.customer_locale : undefined;
// Respond 200 immediately and run the (slow) PDF + email work in the
// background — keeps us well under Shopify's ~5s ack timeout. Dedupe
// above guarantees we don't double-process a retry while the first
// delivery is still working.
runWebhookInBackground(`${topic} order=${orderId} shop=${shop}`, async () => {
const settings = await db.shopSettings.findUnique({ where: { shopDomain: shop } });
if (!settings?.autoEmailOnWireTransferPlaced) return;
const orderGid = `gid://shopify/Order/${String(orderId).replace(/^.*\//, "")}`;
if (!(await isManualPaymentOrder(admin, orderGid))) return;
try {
const result = await generateAndEmailInvoice({
shopDomain: shop,
admin,
orderId,
customerLocale: typeof payload?.customer_locale === "string" ? payload.customer_locale : undefined,
customerLocale,
});
if (!result.ok) {
console.warn(`auto-email (wire-transfer placed) failed for order ${orderId} on ${shop}: ${result.reason}`);
}
} catch (err) {
console.error(`auto-email (wire-transfer placed) crashed for order ${orderId} on ${shop}:`, err);
console.warn(
`auto-email (wire-transfer placed) failed for order ${orderId} on ${shop}: ${result.reason}`,
);
}
});
return new Response();
};
+17 -9
View File
@@ -5,6 +5,8 @@ import {
generateAndEmailInvoice,
isManualPaymentOrder,
} from "../services/invoice/automations.server";
import { isDuplicateWebhook } from "../services/webhooks/dedupe.server";
import { runWebhookInBackground } from "../services/webhooks/background.server";
/**
* orders/fulfilled — Automation 2: when an order is fulfilled and is NOT a
@@ -16,36 +18,42 @@ export const action = async ({ request }: ActionFunctionArgs) => {
const { shop, topic, payload, session, admin } = await authenticate.webhook(request);
console.log(`Received ${topic} webhook for ${shop}`);
// Idempotency against Shopify retries — see webhooks/dedupe.server.ts.
if (await isDuplicateWebhook(request, shop, topic)) return new Response();
if (!session || !admin) {
// App was uninstalled before the webhook drained — nothing to do.
return new Response();
}
const settings = await db.shopSettings.findUnique({ where: { shopDomain: shop } });
if (!settings?.autoEmailOnFulfilledNonWireTransfer) return new Response();
const orderId = payload?.id;
if (orderId == null) return new Response();
const customerLocale =
typeof payload?.customer_locale === "string" ? payload.customer_locale : undefined;
// Respond fast; do the heavy lifting after the response (see notes in
// webhooks.orders.create.tsx for the rationale).
runWebhookInBackground(`${topic} order=${orderId} shop=${shop}`, async () => {
const settings = await db.shopSettings.findUnique({ where: { shopDomain: shop } });
if (!settings?.autoEmailOnFulfilledNonWireTransfer) return;
const orderGid = `gid://shopify/Order/${String(orderId).replace(/^.*\//, "")}`;
if (await isManualPaymentOrder(admin, orderGid)) {
// Manual / wire-transfer order — handled by Automation 1, skip here.
return new Response();
return;
}
try {
const result = await generateAndEmailInvoice({
shopDomain: shop,
admin,
orderId,
customerLocale: typeof payload?.customer_locale === "string" ? payload.customer_locale : undefined,
customerLocale,
});
if (!result.ok) {
console.warn(`auto-email (fulfilled) failed for order ${orderId} on ${shop}: ${result.reason}`);
}
} catch (err) {
console.error(`auto-email (fulfilled) crashed for order ${orderId} on ${shop}:`, err);
}
});
return new Response();
};
+3
View File
@@ -1,10 +1,13 @@
import type { ActionFunctionArgs } from "react-router";
import { authenticate } from "../shopify.server";
import { isDuplicateWebhook } from "../services/webhooks/dedupe.server";
// Acknowledged but not yet acted on. Future: invalidate cached invoice
// snapshots when a relevant field on the order changes.
export const action = async ({ request }: ActionFunctionArgs) => {
const { shop, topic } = await authenticate.webhook(request);
console.log(`Received ${topic} webhook for ${shop}`);
// Idempotency against Shopify retries — see webhooks/dedupe.server.ts.
if (await isDuplicateWebhook(request, shop, topic)) return new Response();
return new Response();
};
+10 -2
View File
@@ -167,11 +167,19 @@ const en: InvoiceStrings = {
paidStamp: "PAID",
};
// Locale → invoice language. We only render in German (`de`) when the
// caller is explicitly German-speaking (de, de-AT, de-DE, de_CH, …).
// Everything else (it, fr, es, en, …) falls back to English so that
// non-German-speaking customers don't receive a German invoice. Callers
// that have a per-shop default fall back to it via
// `pickLanguage(customerLocale ?? settings.defaultLanguage)`, which is why
// `null`/`undefined` still maps to `de` (the legacy default for the
// Austrian shops this app was built for).
export function pickLanguage(input: string | null | undefined): InvoiceLanguage {
if (!input) return "de";
const v = input.toLowerCase();
if (v.startsWith("en")) return "en";
return "de";
if (v.startsWith("de")) return "de";
return "en";
}
export function getStrings(language: InvoiceLanguage): InvoiceStrings {
@@ -0,0 +1,27 @@
/**
* Fire-and-forget runner for webhook side-effects.
*
* Shopify expects a 200 response within ~5 seconds, otherwise it considers
* the delivery failed and retries it. Heavy automation work (PDF render,
* Shopify Files upload, SMTP send) routinely exceeded that budget, which
* caused duplicate invoice emails before we added the dedupe table.
*
* Returning the response immediately and letting the work finish in the
* background keeps Shopify happy. Combined with the dedupe table this is
* defence-in-depth: dedupe ensures *correctness* even if a retry sneaks
* through, while async processing makes retries unlikely in the first
* place.
*
* Errors are caught and logged \u2014 they cannot reach a dispatcher because
* the HTTP response is already gone.
*/
export function runWebhookInBackground(
description: string,
work: () => Promise<unknown>,
): void {
// `void` so we don't accidentally `await` the floating promise; the
// node event loop keeps the task alive until it settles.
void work().catch((err) => {
console.error(`background webhook task '${description}' failed:`, err);
});
}
+67
View File
@@ -0,0 +1,67 @@
import db from "../../db.server";
/**
* Minimal shape of the Prisma client surface we use — declared inline so
* the helper can be unit-tested with a tiny stub instead of pulling in a
* real database.
*/
export interface DedupeDeps {
db: {
processedWebhook: {
create: (args: {
data: { webhookId: string; topic: string; shopDomain: string };
}) => Promise<unknown>;
};
};
}
/**
* Returns `true` when this Shopify webhook delivery has already been
* processed and the caller should short-circuit without doing the work.
*
* Shopify retries webhook deliveries when it doesn't receive a 200 within
* its (~5s) timeout window. Without dedupe this caused us to email an
* invoice twice for the same order: the first slow delivery completed its
* work but Shopify timed out and re-sent the webhook, which then ran the
* automation a second time.
*
* We key on the `X-Shopify-Webhook-Id` header — Shopify guarantees the same
* value for retries of the same delivery, but a new value for genuinely
* new events. The insert is the lock: a unique-constraint violation
* (Prisma error code `P2002`) means another delivery already claimed this
* id.
*/
export async function isDuplicateWebhook(
request: Request,
shop: string,
topic: string,
deps: DedupeDeps = { db },
): Promise<boolean> {
const webhookId = request.headers.get("x-shopify-webhook-id");
if (!webhookId) {
// Defensive: in unit tests / non-Shopify callers there is no id.
// Don't dedupe — that would silently drop legitimate calls.
return false;
}
try {
await deps.db.processedWebhook.create({
data: { webhookId, topic, shopDomain: shop },
});
return false;
} catch (err) {
// Duck-typed P2002 check so callers can stub the db without pulling
// in the real `Prisma` namespace.
if ((err as { code?: string } | null)?.code === "P2002") {
console.log(
`dedupe: skipping duplicate ${topic} delivery for ${shop} (webhookId=${webhookId})`,
);
return true;
}
// Don't fail the webhook on a logging-table issue; just process it.
console.warn(
`dedupe: failed to record webhook ${webhookId} (${topic}/${shop}):`,
err,
);
return false;
}
}
+17
View File
@@ -12,6 +12,7 @@
"@prisma/client": "^6.16.3",
"@react-pdf/renderer": "^4.5.1",
"@react-router/dev": "^7.12.0",
"@react-router/express": "^7.14.2",
"@react-router/fs-routes": "^7.12.0",
"@react-router/node": "^7.12.0",
"@react-router/serve": "^7.12.0",
@@ -26,7 +27,10 @@
"@tiptap/react": "^3.23.1",
"@tiptap/starter-kit": "^3.23.1",
"@types/nodemailer": "^8.0.0",
"compression": "^1.8.1",
"express": "^4.22.1",
"isbot": "^5.1.31",
"morgan": "^1.10.1",
"nodemailer": "^8.0.7",
"prisma": "^6.16.3",
"qrcode": "^1.5.4",
@@ -61,6 +65,15 @@
"node": ">=20.19 <22 || >=22.12"
}
},
"extensions/customer-account-payment": {
"version": "1.0.0",
"devDependencies": {
"@preact/signals": "^1.3.0",
"@shopify/ui-extensions": "^2026.1.0",
"preact": "^10.22.0",
"typescript": "^5.6.0"
}
},
"extensions/invoice-order-action": {
"version": "1.0.0",
"devDependencies": {
@@ -6670,6 +6683,10 @@
"integrity": "sha512-z1HGKcYy2xA8AGQfwrn0PAy+PB7X/GSj3UVJW9qKyn43xWa+gl5nXmU4qqLMRzWVLFC8KusUX8T/0kCiOYpAIQ==",
"license": "MIT"
},
"node_modules/customer-account-payment": {
"resolved": "extensions/customer-account-payment",
"link": true
},
"node_modules/damerau-levenshtein": {
"version": "1.0.8",
"resolved": "https://registry.npmjs.org/damerau-levenshtein/-/damerau-levenshtein-1.0.8.tgz",
+7 -2
View File
@@ -9,7 +9,7 @@
"deploy": "shopify app deploy",
"config:use": "shopify app config use",
"env": "shopify app env",
"start": "react-router-serve ./build/server/index.js",
"start": "node ./server.js",
"docker-start": "npm run setup && npm run start",
"setup": "prisma generate && prisma migrate deploy",
"lint": "eslint --ignore-path .gitignore --cache --cache-location ./node_modules/.cache/eslint .",
@@ -17,7 +17,8 @@
"prisma": "prisma",
"graphql-codegen": "graphql-codegen",
"vite": "vite",
"typecheck": "react-router typegen && tsc --noEmit"
"typecheck": "react-router typegen && tsc --noEmit",
"test": "tsx --test tests"
},
"type": "module",
"engines": {
@@ -29,7 +30,11 @@
"@react-router/dev": "^7.12.0",
"@react-router/fs-routes": "^7.12.0",
"@react-router/node": "^7.12.0",
"@react-router/express": "^7.14.2",
"@react-router/serve": "^7.12.0",
"compression": "^1.8.1",
"express": "^4.22.1",
"morgan": "^1.10.1",
"@shopify/app-bridge-react": "^4.2.4",
"@shopify/shopify-app-react-router": "^1.1.0",
"@shopify/shopify-app-session-storage-prisma": "^8.0.0",
@@ -0,0 +1,13 @@
-- Idempotency table for inbound Shopify webhooks. We insert a row keyed on
-- the X-Shopify-Webhook-Id header at the start of webhook processing; a
-- duplicate insert (P2002) means Shopify retried a delivery we've already
-- seen, so we short-circuit and return 200 without doing the work twice.
CREATE TABLE "ProcessedWebhook" (
"webhookId" TEXT NOT NULL PRIMARY KEY,
"topic" TEXT NOT NULL,
"shopDomain" TEXT NOT NULL,
"receivedAt" DATETIME NOT NULL DEFAULT CURRENT_TIMESTAMP
);
CREATE INDEX "ProcessedWebhook_shopDomain_topic_idx"
ON "ProcessedWebhook"("shopDomain", "topic");
+11
View File
@@ -182,6 +182,17 @@ model EmailLog {
@@index([shopDomain, invoiceId])
}
// Idempotency table for inbound Shopify webhooks. See
// `app/services/webhooks/dedupe.server.ts` for details.
model ProcessedWebhook {
webhookId String @id
topic String
shopDomain String
receivedAt DateTime @default(now())
@@index([shopDomain, topic])
}
// Per-shop logo bytes cache. Avoids fetching the logo from Shopify Files on
// every PDF render.
model LogoCache {
+81
View File
@@ -0,0 +1,81 @@
// Custom production server for the React Router build.
//
// Replaces `react-router-serve` so we can:
// - prefix every console line with an ISO timestamp,
// - use a richer morgan format (with timestamp + content-length),
// - skip access logs for successful /healthz probes (they would otherwise
// drown out everything useful — Docker/Caddy poll them every couple of
// seconds).
//
// Behaviour is otherwise intentionally identical to `@react-router/serve`'s
// CLI (compression, /assets immutable cache, public/ static, SIGTERM/SIGINT
// handling).
import { createRequestHandler } from "@react-router/express";
import compression from "compression";
import express from "express";
import morgan from "morgan";
// ---------------------------------------------------------------------------
// Console timestamps — patch BEFORE anything else logs.
// ---------------------------------------------------------------------------
const ts = () => `[${new Date().toISOString()}]`;
for (const level of ["log", "info", "warn", "error", "debug"]) {
const original = console[level].bind(console);
console[level] = (...args) => original(ts(), ...args);
}
const PORT = Number(process.env.PORT || 3000);
const HOST = process.env.HOST;
const buildModule = await import("./build/server/index.js");
const build = buildModule.default ?? buildModule;
const app = express();
app.disable("x-powered-by");
app.use(compression());
// Static assets emitted by the React Router build.
app.use(
"/assets",
express.static("build/client/assets", { immutable: true, maxAge: "1y" }),
);
app.use(express.static("build/client", { maxAge: "1h" }));
app.use(express.static("public", { maxAge: "1h" }));
// Access log: ISO timestamp + standard request info; suppress healthy
// /healthz polls so real traffic stays visible.
morgan.token("isotime", () => new Date().toISOString());
app.use(
morgan(
":isotime :method :url :status :res[content-length] - :response-time ms",
{
skip: (req, res) => req.url === "/healthz" && res.statusCode < 400,
},
),
);
app.all(
"*",
createRequestHandler({ build, mode: process.env.NODE_ENV }),
);
const onListen = () => {
console.log(
`[server] listening on http://${HOST ?? "localhost"}:${PORT}`,
);
};
const server = HOST
? app.listen(PORT, HOST, onListen)
: app.listen(PORT, onListen);
for (const signal of ["SIGTERM", "SIGINT"]) {
process.once(signal, () => {
console.log(`[server] received ${signal}, shutting down`);
server.close((err) => {
if (err) console.error("[server] close error:", err);
process.exit(0);
});
});
}
+79
View File
@@ -0,0 +1,79 @@
import { strict as assert } from "node:assert";
import { describe, it } from "node:test";
import { pickLanguage } from "../app/services/invoice/i18n";
import { isDuplicateWebhook, type DedupeDeps } from "../app/services/webhooks/dedupe.server";
describe("pickLanguage", () => {
it("returns 'de' only for explicit German locales", () => {
assert.equal(pickLanguage("de"), "de");
assert.equal(pickLanguage("de-AT"), "de");
assert.equal(pickLanguage("de-DE"), "de");
assert.equal(pickLanguage("de_CH"), "de");
assert.equal(pickLanguage("DE-AT"), "de"); // case-insensitive
});
it("returns 'en' for non-German locales (regression: it/fr/es no longer fall back to de)", () => {
assert.equal(pickLanguage("en"), "en");
assert.equal(pickLanguage("en-US"), "en");
assert.equal(pickLanguage("it"), "en");
assert.equal(pickLanguage("it-IT"), "en");
assert.equal(pickLanguage("fr"), "en");
assert.equal(pickLanguage("fr-FR"), "en");
assert.equal(pickLanguage("es"), "en");
assert.equal(pickLanguage("hu-HU"), "en");
});
it("falls back to 'de' for empty/unknown input so the per-shop default chain still works", () => {
assert.equal(pickLanguage(undefined), "de");
assert.equal(pickLanguage(null), "de");
assert.equal(pickLanguage(""), "de");
});
});
function makeRequest(headers: Record<string, string> = {}): Request {
return new Request("https://example.com/webhooks/test", {
method: "POST",
headers,
});
}
function makeDeps(behaviour: "ok" | "p2002" | "boom"): DedupeDeps {
return {
db: {
processedWebhook: {
create: async () => {
if (behaviour === "ok") return {};
if (behaviour === "p2002") {
const err = new Error("Unique constraint failed") as Error & { code?: string };
err.code = "P2002";
throw err;
}
throw new Error("DB unavailable");
},
},
},
};
}
describe("isDuplicateWebhook", () => {
it("returns false on first delivery (insert succeeds)", async () => {
const req = makeRequest({ "x-shopify-webhook-id": "abc-123" });
assert.equal(await isDuplicateWebhook(req, "shop.myshopify.com", "ORDERS_CREATE", makeDeps("ok")), false);
});
it("returns true on a retried delivery (P2002)", async () => {
const req = makeRequest({ "x-shopify-webhook-id": "abc-123" });
assert.equal(await isDuplicateWebhook(req, "shop.myshopify.com", "ORDERS_CREATE", makeDeps("p2002")), true);
});
it("returns false (and proceeds) when the dedupe table itself errors \u2014 fail-open, never drop a webhook silently", async () => {
const req = makeRequest({ "x-shopify-webhook-id": "abc-123" });
assert.equal(await isDuplicateWebhook(req, "shop.myshopify.com", "ORDERS_CREATE", makeDeps("boom")), false);
});
it("returns false when the X-Shopify-Webhook-Id header is missing (test harness / non-Shopify caller)", async () => {
const req = makeRequest();
assert.equal(await isDuplicateWebhook(req, "shop.myshopify.com", "ORDERS_CREATE", makeDeps("ok")), false);
});
});