Skip to content

Commit b150df3

Browse files
fix(billing): sentinel backfill + trialing guard + intentId + structured logger
C1 — add SENTINEL_PENDING constant + isUnresolved() helper; PI backfill resolver in handleChargeRefunded recovers real cs_* session id from PaymentIntent metadata when charge.metadata has __pending__; defensive guard in refundPartial rejects residual sentinels. H1 — createCheckout live-sub check uses status:'all' + find for ['active','trialing'] (was status:'active', silently missed trialing subscriptions). H2 — ExtrasCheckoutRequest Zod schema adds intentId z.string().max(180); createExtrasCheckout accepts intentId; idempotency key is stable intentId-derived or minute-bucketed fallback. H3 — all 7 console.error/warn sites in billing.webhook.service replaced with structured logger.error/warn calls including { error, stack } context objects. Tests: 44 billing suites, 657 tests all green. billing.usage.endpoint mock extended to cover billing.extra.service import side-effect (logger instantiation in test context).
1 parent 4296991 commit b150df3

10 files changed

Lines changed: 391 additions & 60 deletions

modules/billing/lib/billing.constants.js

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,17 @@
33
*/
44
import config from '../../../config/index.js';
55

6+
/**
7+
* Sentinel value written to stripeSessionId during extras checkout session creation.
8+
* Stripe forbids a session from self-referencing its own id at creation time, so this
9+
* placeholder is used in both session.metadata and payment_intent_data.metadata.
10+
* After checkout.session.completed fires, the real cs_* id is patched onto the
11+
* PaymentIntent metadata — but Stripe Charge metadata is a one-time snapshot copied
12+
* at charge creation, so charge.metadata.stripeSessionId may still carry this sentinel
13+
* on refunds. Treat it as "unresolved" and trigger the PI backfill path.
14+
*/
15+
export const SENTINEL_PENDING = '__pending__';
16+
617
export const DEFAULT_METER_RUN_BASE = 1;
718
export const DEFAULT_CRON_JITTER_MAX_MS = 60_000;
819
export const DEFAULT_PLAN_CHANGE_PRESERVE_USAGE = true;

modules/billing/models/billing.subscription.schema.js

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -80,7 +80,9 @@ const ExtrasCheckoutRequest = z
8080
cancelUrl: z.string().url('cancelUrl must be a valid URL'),
8181
// Caller-provided stable intent ID for idempotency (prevents double-click double-charge).
8282
// When absent, a soft-stable minute-bucketed key is used as fallback.
83-
intentId: z.string().min(1).optional(),
83+
// Max 180 chars: Stripe idempotency key limit is 255; the prefix
84+
// `extras_checkout_{orgId}_{packId}_` consumes ~64 chars, leaving ~10 chars margin.
85+
intentId: z.string().min(1).max(180).optional(),
8486
})
8587
.strict();
8688

modules/billing/services/billing.extra.service.js

Lines changed: 34 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import config from '../../../config/index.js';
55
import logger from '../../../lib/services/logger.js';
66
import billingEvents from '../lib/events.js';
77
import BillingExtraBalanceRepository from '../repositories/billing.extraBalance.repository.js';
8+
import { SENTINEL_PENDING } from '../lib/billing.constants.js';
89

910
/**
1011
* @function creditPack
@@ -80,22 +81,53 @@ const expireOldEntries = (orgId) =>
8081
* original units were already consumed — this is the correct economic reflection
8182
* (the debt persists until the next creditPack replenishes it).
8283
*
84+
* Defensive sentinel guard: if called with stripeSessionId === SENTINEL_PENDING,
85+
* it means the upstream caller failed to resolve the real session ID before calling.
86+
* Immediately return sentinel_unresolved to prevent a ledger lookup against a
87+
* placeholder value that will never match any topup entry.
88+
*
8389
* @param {string} orgId - The organization ObjectId (string).
8490
* @param {string} stripeSessionId - Stripe session ID of the original purchase (to find the pack).
8591
* @param {number} amountRefundedCents - Amount refunded in cents (integer).
8692
* @param {string|undefined} [packId] - Optional pack identifier from Stripe metadata for exact correlation.
8793
* @param {string|undefined} [stripeRefundId] - Stripe refund object ID (e.g. rf_xxx). When present, used as
8894
* primary idempotency key. When absent (legacy callers), falls back to session+amount+topupId composite.
8995
* @returns {Promise<{doc: Object|null, applied: boolean, refundUnits: number, reason?: string}>}
90-
* `reason` is present only when `applied === false`: 'meter_mode_disabled' | 'invalid_org' |
91-
* 'pack_not_found' | 'ambiguous_pack_match'.
96+
* `reason` is present only when `applied === false`: 'meter_mode_disabled' | 'sentinel_unresolved' |
97+
* 'invalid_org' | 'pack_not_found' | 'ambiguous_pack_match'.
9298
*/
9399
// biome-ignore lint/correctness/useQwikValidLexicalScope: false positive — Node.js service, not Qwik
94100
const refundPartial = async (orgId, stripeSessionId, amountRefundedCents, packId, stripeRefundId) => {
95101
if (!config?.billing?.meterMode) {
96102
return { doc: null, applied: false, reason: 'meter_mode_disabled', refundUnits: 0 };
97103
}
98104

105+
// Defensive sentinel guard — belt-and-suspenders in case the upstream caller missed
106+
// the isUnresolved() check in handleChargeRefunded. A sentinel stripeSessionId can
107+
// never match any topup ledger entry, so skip immediately rather than silently no-op.
108+
if (stripeSessionId === SENTINEL_PENDING) {
109+
logger.error('[billing.extra] refundPartial called with sentinel stripeSessionId — upstream missed isUnresolved() check', {
110+
orgId,
111+
amountRefundedCents,
112+
packId,
113+
stripeRefundId,
114+
});
115+
try {
116+
billingEvents.emit('billing.refund.unresolved', {
117+
reason: 'sentinel_unresolved',
118+
orgId,
119+
amountRefundedCents,
120+
stripeRefundId,
121+
});
122+
} catch (evtErr) {
123+
logger.error('[billing.extra] billing.refund.unresolved listener error (non-fatal)', {
124+
error: evtErr?.message ?? String(evtErr),
125+
stack: evtErr?.stack,
126+
});
127+
}
128+
return { doc: null, applied: false, reason: 'sentinel_unresolved', refundUnits: 0 };
129+
}
130+
99131
// Find the topup ledger entry for this session to identify the pack
100132
const doc = await BillingExtraBalanceRepository.getOrCreate(orgId);
101133
if (!doc) return { doc: null, applied: false, reason: 'invalid_org', refundUnits: 0 };

modules/billing/services/billing.service.js

Lines changed: 13 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ import getStripe from '../lib/stripe.js';
66
import BillingPlansService from './billing.plans.service.js';
77
import SubscriptionRepository from '../repositories/billing.subscription.repository.js';
88
import { isDuplicateKeyError } from '../lib/billing.errors.js';
9+
import { SENTINEL_PENDING } from '../lib/billing.constants.js';
910

1011
/**
1112
* Validate that a redirect URL is safe for the current environment.
@@ -148,14 +149,17 @@ const createCheckout = async (organization, priceId, successUrl, cancelUrl) => {
148149

149150
// Server-side active subscription guard — closes race window between local-DB check and
150151
// stripe.checkout.sessions.create (webhook may have arrived mid-flight).
152+
// Fetches status:'all' and filters locally to cover both 'active' AND 'trialing' in one call
153+
// (Stripe's status filter accepts only a single string, not an array).
151154
// +1 Stripe API call cost; acceptable given infrequent checkout entry point.
152155
if (subscription.stripeCustomerId) {
153-
const liveActiveSubs = await stripe.subscriptions.list({
156+
const liveSubs = await stripe.subscriptions.list({
154157
customer: subscription.stripeCustomerId,
155-
status: 'active',
156-
limit: 1,
158+
status: 'all',
159+
limit: 10,
157160
});
158-
if (liveActiveSubs.data.length > 0) {
161+
const blockingSub = liveSubs.data.find((s) => ['active', 'trialing'].includes(s.status));
162+
if (blockingSub) {
159163
const portalUrl = await createPortalSession(organization);
160164
const err = new Error('Subscription already active');
161165
err.statusCode = 409;
@@ -206,6 +210,7 @@ const createCheckout = async (organization, priceId, successUrl, cancelUrl) => {
206210
* When provided: key = `extras_checkout_{orgId}_{packId}_{intentId}` (fully stable).
207211
* When absent: key bucketed to the minute — prevents instant double-click but not
208212
* cross-minute replay. Callers should pass a UUID generated on button click.
213+
* Max 180 chars (Stripe idempotency key limit is 255; prefix consumes ~64 chars).
209214
* @returns {Promise<{url: String}>} Object with the Checkout session URL
210215
*/
211216
// biome-ignore lint/correctness/useQwikValidLexicalScope: false positive — Node.js service, not Qwik
@@ -244,17 +249,17 @@ const createExtrasCheckout = async (organization, packId, successUrl, cancelUrl,
244249
success_url: successUrl,
245250
cancel_url: cancelUrl,
246251
metadata: {
247-
organizationId: String(organization._id),
252+
organizationId: orgId,
248253
packId,
249254
kind: 'extras',
250-
stripeSessionId: '__pending__',
255+
stripeSessionId: SENTINEL_PENDING,
251256
},
252257
payment_intent_data: {
253258
metadata: {
254-
organizationId: String(organization._id),
259+
organizationId: orgId,
255260
packId,
256261
kind: 'extras',
257-
stripeSessionId: '__pending__',
262+
stripeSessionId: SENTINEL_PENDING,
258263
},
259264
},
260265
};

modules/billing/services/billing.webhook.service.js

Lines changed: 73 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,19 @@ import OrganizationRepository from '../../organizations/repositories/organizatio
1212
import BillingExtraService from './billing.extra.service.js';
1313
import BillingResetService from './billing.reset.service.js';
1414
import billingEvents from '../lib/events.js';
15+
import { SENTINEL_PENDING } from '../lib/billing.constants.js';
16+
17+
/**
18+
* Treats a stripeSessionId as "unresolved" when absent, empty, or still the
19+
* creation-time sentinel placeholder written before Stripe assigned a real cs_* id.
20+
* Stripe Charge metadata is a one-time snapshot copied at charge creation — later
21+
* PaymentIntent metadata patches do NOT propagate back, so charge.metadata.stripeSessionId
22+
* may permanently carry SENTINEL_PENDING for any charge created during the brief window
23+
* between session.create and checkout.session.completed.
24+
* @param {string|undefined} id
25+
* @returns {boolean}
26+
*/
27+
const isUnresolved = (id) => !id || id === SENTINEL_PENDING;
1528

1629
/**
1730
* Maximum number of handler execution attempts before an event is dead-lettered.
@@ -112,14 +125,14 @@ const withIdempotency = async (event, handler) => {
112125
}
113126

114127
// Rollback claim so Stripe can retry on a fresh delivery.
115-
try {
116-
await ProcessedStripeEventRepository.deleteByEventId(eventId);
117-
} catch (rollbackErr) {
128+
// Swallow rollback errors so the original handler error is always propagated.
129+
await ProcessedStripeEventRepository.deleteByEventId(event.id).catch((rollbackErr) => {
118130
logger.error('[billing.webhook] rollback deleteByEventId failed — event may be stuck', {
119-
eventId,
120-
error: rollbackErr?.message ?? rollbackErr,
131+
eventId: event.id,
132+
error: rollbackErr?.message ?? String(rollbackErr),
133+
stack: rollbackErr?.stack,
121134
});
122-
}
135+
});
123136
throw err;
124137
}
125138
};
@@ -185,6 +198,11 @@ const handleCheckoutCompleted = async (session) => {
185198
* @description Handle checkout.session.completed for mode='payment' — credit extras pack.
186199
* Extracts organizationId, packId, kind from session metadata.
187200
* Skips silently if payment_status !== 'paid', kind !== 'extras', or metadata is incomplete.
201+
* Backfills PaymentIntent metadata with the real cs_* session ID so that
202+
* charge.refunded events can correlate the charge back to the correct ledger entry.
203+
* At session creation time stripeSessionId is set to SENTINEL_PENDING (Stripe forbids
204+
* self-reference). Charge.metadata is a one-time snapshot, so the PI patch is best-effort;
205+
* handleChargeRefunded has a backfill resolver as a secondary defence.
188206
* @param {Object} session - Stripe checkout session object (mode='payment')
189207
* @returns {Promise<void>}
190208
*/
@@ -203,7 +221,7 @@ const handleCheckoutPaymentCompleted = async (session) => {
203221

204222
// Backfill PaymentIntent metadata with the real session ID so that charge.refunded
205223
// events can correlate the charge back to this ledger entry.
206-
// At session.create time stripeSessionId was set to '__pending__' (Stripe forbids
224+
// At session.create time stripeSessionId was set to SENTINEL_PENDING (Stripe forbids
207225
// self-reference). Propagating the real cs_* ID here ensures charge.metadata carries
208226
// it when a refund is issued later.
209227
if (paymentIntentId) {
@@ -215,12 +233,16 @@ const handleCheckoutPaymentCompleted = async (session) => {
215233
organizationId,
216234
packId,
217235
kind: 'extras',
218-
stripeSessionId, // real cs_* ID
236+
stripeSessionId, // real cs_* ID (replaces SENTINEL_PENDING)
219237
},
220238
});
221239
} catch (err) {
222-
// Log but don't fail — refund correlation may need fallback path
223-
console.warn('[billing.webhook] PaymentIntent metadata update failed:', err.message);
240+
// Log but don't fail — refund correlation may use the backfill resolver path
241+
logger.warn('[billing.webhook] PaymentIntent metadata update failed', {
242+
paymentIntentId,
243+
error: err?.message ?? String(err),
244+
stack: err?.stack,
245+
});
224246
}
225247
}
226248
}
@@ -289,7 +311,10 @@ const handleSubscriptionUpdated = async (subscription, event) => {
289311
});
290312
} catch (evtErr) {
291313
// Listener errors must not disrupt webhook processing — log for traceability
292-
console.error('[billing.webhook] plan.changed listener error (non-fatal):', evtErr?.message ?? evtErr);
314+
logger.error('[billing.webhook] plan.changed listener error (non-fatal)', {
315+
error: evtErr?.message ?? String(evtErr),
316+
stack: evtErr?.stack,
317+
});
293318
}
294319

295320
// Plan switch mid-cycle = refresh the active week snapshot to the new plan.
@@ -307,10 +332,10 @@ const handleSubscriptionUpdated = async (subscription, event) => {
307332
await BillingResetService.forceRotateForPlanChange(organizationId, { preserveUsage: true });
308333
} catch (err) {
309334
planChangeResetTriggered = false;
310-
console.error(
311-
'[billing.webhook] forceRotateForPlanChange failed, falling back to resetWeek:',
312-
err?.message ?? err,
313-
);
335+
logger.error('[billing.webhook] forceRotateForPlanChange failed, falling back to resetWeek', {
336+
error: err?.message ?? String(err),
337+
stack: err?.stack,
338+
});
314339
}
315340
}
316341
}
@@ -328,7 +353,10 @@ const handleSubscriptionUpdated = async (subscription, event) => {
328353
await BillingResetService.resetWeek(organizationId, newPeriodStart);
329354
} catch (err) {
330355
// Log for monitoring — not thrown so webhook processing continues
331-
console.error('[billing.webhook] resetWeek failed (non-fatal):', err?.message ?? err);
356+
logger.error('[billing.webhook] resetWeek failed (non-fatal)', {
357+
error: err?.message ?? String(err),
358+
stack: err?.stack,
359+
});
332360
}
333361
}
334362
};
@@ -360,7 +388,10 @@ const handleSubscriptionDeleted = async (subscription, event) => {
360388
await BillingResetService.forceRotateForPlanChange(organizationId, { preserveUsage: false });
361389
} catch (err) {
362390
// Log for monitoring — not thrown so webhook processing continues
363-
console.error('[billing.webhook] forceRotateForPlanChange on cancel failed (non-fatal):', err?.message ?? err);
391+
logger.error('[billing.webhook] forceRotateForPlanChange on cancel failed (non-fatal)', {
392+
error: err?.message ?? String(err),
393+
stack: err?.stack,
394+
});
364395
}
365396
};
366397

@@ -398,7 +429,10 @@ const handleInvoicePaymentFailed = async (invoice, event) => {
398429
billingEvents.emit('payment.failed', { organizationId });
399430
} catch (evtErr) {
400431
// Listener errors must not disrupt webhook processing — log for traceability
401-
console.error('[billing.webhook] payment.failed listener error (non-fatal):', evtErr?.message ?? evtErr);
432+
logger.error('[billing.webhook] payment.failed listener error (non-fatal)', {
433+
error: evtErr?.message ?? String(evtErr),
434+
stack: evtErr?.stack,
435+
});
402436
}
403437
};
404438

@@ -452,6 +486,12 @@ const handleInvoicePaymentSucceeded = async (invoice, event) => {
452486
* Each refund's rf_ id is used as the idempotency key, making webhook replay safe.
453487
* Individual entries are silently skipped when: metadata is incomplete, refund amount
454488
* is absent/zero, or the refund object has no id.
489+
*
490+
* SENTINEL handling: at session.create time stripeSessionId is set to SENTINEL_PENDING
491+
* ('__pending__'). Stripe Charge metadata is a one-time snapshot — even though
492+
* checkout.session.completed patches the PaymentIntent with the real cs_* id,
493+
* charge.metadata.stripeSessionId may permanently carry SENTINEL_PENDING.
494+
* Both absent AND sentinel values trigger the PI backfill resolver path.
455495
* @param {Object} charge - Stripe charge object
456496
* @returns {Promise<void>}
457497
*/
@@ -466,8 +506,10 @@ const handleChargeRefunded = async (charge) => {
466506

467507
if (!organizationId || !mongoose.Types.ObjectId.isValid(organizationId)) return;
468508

469-
// Backfill resolver: if stripeSessionId is missing, fetch the PaymentIntent to find it.
470-
if (!stripeSessionId && paymentIntentId) {
509+
// Backfill resolver: if stripeSessionId is missing OR carries SENTINEL_PENDING,
510+
// fetch the PaymentIntent to find the real session ID patched by checkout.session.completed.
511+
// isUnresolved() treats both falsy values and the sentinel string as "unresolved".
512+
if (isUnresolved(stripeSessionId) && paymentIntentId) {
471513
const stripe = getStripe();
472514
if (stripe) {
473515
try {
@@ -482,12 +524,17 @@ const handleChargeRefunded = async (charge) => {
482524
}
483525
}
484526
} catch (err) {
485-
logger.error('[billing] refund PI fetch failed', { chargeId: charge.id, paymentIntentId, error: err?.message });
527+
logger.error('[billing] refund PI fetch failed', {
528+
chargeId: charge.id,
529+
paymentIntentId,
530+
error: err?.message ?? String(err),
531+
stack: err?.stack,
532+
});
486533
}
487534
}
488535
}
489536

490-
if (!stripeSessionId) {
537+
if (isUnresolved(stripeSessionId)) {
491538
// Could not resolve stripeSessionId from charge or PaymentIntent metadata.
492539
// Emit alert event and log for manual reconciliation.
493540
const refundAmount = charge.refunds?.data?.reduce((sum, r) => sum + (r.amount ?? 0), 0) ?? 0;
@@ -499,7 +546,10 @@ const handleChargeRefunded = async (charge) => {
499546
try {
500547
billingEvents.emit('billing.refund.unresolved', { chargeId: charge.id, paymentIntentId, refundAmount });
501548
} catch (evtErr) {
502-
console.error('[billing.webhook] billing.refund.unresolved listener error (non-fatal):', evtErr?.message ?? evtErr);
549+
logger.error('[billing.webhook] billing.refund.unresolved listener error (non-fatal)', {
550+
error: evtErr?.message ?? String(evtErr),
551+
stack: evtErr?.stack,
552+
});
503553
}
504554
return;
505555
}

modules/billing/tests/billing.checkout.unit.tests.js

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -37,7 +37,7 @@ describe('Billing service unit tests:', () => {
3737
},
3838
},
3939
subscriptions: {
40-
// Server-side active-sub guard (Item 9): returns no active subs by default
40+
// Default: no live active/trialing subs — checkout proceeds
4141
list: jest.fn().mockResolvedValue({ data: [] }),
4242
},
4343
};

0 commit comments

Comments
 (0)