From def6cc2d2e9c355320cb13e7d532854076232b31 Mon Sep 17 00:00:00 2001 From: Vasilica Olariu Date: Wed, 3 Dec 2025 18:09:01 +0200 Subject: [PATCH 1/2] PS-469 - add more logs in admin service & payment service to track payment changes & payment reconciliation --- src/api/admin/admin.service.ts | 93 ++++++++++++++++++- .../trolley/handlers/tax-form.handler.ts | 42 ++++++++- src/shared/payments/payments.service.ts | 60 ++++++++++-- 3 files changed, 183 insertions(+), 12 deletions(-) diff --git a/src/api/admin/admin.service.ts b/src/api/admin/admin.service.ts index 1d47f7c..d558bf7 100644 --- a/src/api/admin/admin.service.ts +++ b/src/api/admin/admin.service.ts @@ -79,34 +79,58 @@ export class AdminService { let needsReconciliation = false; const winningsId = body.winningsId; + this.logger.info( + `updateWinnings called by ${userId} for winningsId=${winningsId}`, + ); + this.logger.debug(`updateWinnings payload: ${JSON.stringify(body)}`); + try { const payments = await this.getPaymentsByWinningsId( winningsId, body.paymentId, ); + this.logger.debug( + `Found ${payments.length} payment(s) for winningsId=${winningsId}`, + ); if (payments.length === 0) { + this.logger.warn( + `No payments found for winningsId=${winningsId}, paymentId=${body.paymentId}`, + ); throw new NotFoundException('failed to get current payments'); } let releaseDate; if (body.paymentStatus) { releaseDate = await this.getPaymentReleaseDateByWinningsId(winningsId); + this.logger.debug( + `Payment release date for winningsId=${winningsId}: ${releaseDate}`, + ); } const transactions: (( tx: Prisma.TransactionClient, ) => Promise)[] = []; const now = new Date().getTime(); + + // iterate payments and build transaction list payments.forEach((payment) => { + this.logger.debug( + `Processing payment ${payment.payment_id} (installment ${payment.installment_number}) with current status=${payment.payment_status}`, + ); + if ( payment.payment_status && payment.payment_status === PaymentStatus.CANCELLED ) { + this.logger.warn( + `Attempt to update cancelled payment ${payment.payment_id} — rejecting`, + ); throw new BadRequestException('cannot update cancelled winnings'); } let version = payment.version ?? 1; + const queuedActions: string[] = []; if (body.description) { transactions.push((tx) => @@ -129,6 +153,9 @@ export class AdminService { }, }), ); + queuedActions.push( + `update description -> "${body.description}" (version ${version})`, + ); if (payment.installment_number === 1) { transactions.push((tx) => @@ -140,6 +167,7 @@ export class AdminService { tx, ), ); + queuedActions.push('add audit for description change'); } } @@ -171,6 +199,9 @@ export class AdminService { payment.payment_status !== PaymentStatus.ON_HOLD_ADMIN && payment.payment_status !== PaymentStatus.PAID ) { + this.logger.warn( + `Invalid attempt to set OWED for payment ${payment.payment_id} when not on hold admin or paid`, + ); throw new BadRequestException( "cannot put a payment back to owed unless it is on hold by an admin, or it's been paid", ); @@ -180,6 +211,9 @@ export class AdminService { break; default: + this.logger.warn( + `Invalid payment status provided: ${body.paymentStatus}`, + ); throw new BadRequestException('invalid payment status provided'); } @@ -187,6 +221,9 @@ export class AdminService { errMessage && payment.payment_status === PaymentStatus.PROCESSING ) { + this.logger.warn( + `Rejected status change for ${payment.payment_id}: ${errMessage}`, + ); throw new BadRequestException(errMessage); } @@ -201,11 +238,17 @@ export class AdminService { tx, ), ); + queuedActions.push( + `update status ${payment.payment_status} -> ${body.paymentStatus}`, + ); paymentStatus = body.paymentStatus as PaymentStatus; if (body.paymentStatus === PaymentStatus.OWED) { needsReconciliation = true; + this.logger.debug( + `Payment ${payment.payment_id} marked OWED; will trigger reconciliation later`, + ); } if (payment.installment_number === 1) { @@ -218,6 +261,7 @@ export class AdminService { tx, ), ); + queuedActions.push('add audit for status change'); } } @@ -232,6 +276,9 @@ export class AdminService { PaymentStatus.ON_HOLD_ADMIN, ].includes(paymentStatus) ) { + this.logger.warn( + `Cannot update release date for payment ${payment.payment_id} in status ${paymentStatus}`, + ); throw new BadRequestException( `Cannot update release date for payment unless it's in one of the states: ${[ PaymentStatus.OWED, @@ -251,6 +298,9 @@ export class AdminService { tx, ), ); + queuedActions.push( + `update release_date ${payment.release_date?.toISOString()} -> ${newReleaseDate.toISOString()}`, + ); if (payment.installment_number === 1) { transactions.push((tx) => @@ -262,6 +312,7 @@ export class AdminService { tx, ), ); + queuedActions.push('add audit for release date change'); } } @@ -297,6 +348,10 @@ export class AdminService { tx, ), ); + + queuedActions.push( + `update amounts -> ${body.paymentAmount.toFixed(2)} (installment 1)`, + ); } else { transactions.push((tx) => this.updatePaymentAmount( @@ -310,17 +365,35 @@ export class AdminService { tx, ), ); + queuedActions.push( + `update amounts -> total ${body.paymentAmount.toFixed(2)} (installment ${payment.installment_number})`, + ); } } + + this.logger.debug( + `Queued ${queuedActions.length} action(s) for payment ${payment.payment_id}: ${queuedActions.join( + ' ; ', + )}`, + ); }); + this.logger.info( + `Executing ${transactions.length} transaction step(s) for winningsId=${winningsId}`, + ); + // Run all transaction tasks in a single prisma transaction await this.prisma.$transaction(async (tx) => { - for (const transaction of transactions) { - await transaction(tx); + for (let i = 0; i < transactions.length; i++) { + this.logger.debug(`Executing transaction ${i + 1}/${transactions.length}`); + await transactions[i](tx); } }); + this.logger.info( + `Successfully executed transactions for winningsId=${winningsId}`, + ); + if (needsReconciliation) { const winning = await this.prisma.winnings.findFirst({ select: { @@ -332,16 +405,32 @@ export class AdminService { }); if (winning?.winner_id) { + this.logger.info( + `Triggering payments reconciliation for user ${winning.winner_id}`, + ); await this.paymentsService.reconcileUserPayments(winning.winner_id); + this.logger.info( + `Reconciliation triggered for user ${winning.winner_id}`, + ); + } else { + this.logger.warn( + `Needs reconciliation but no winner_id found for winningsId=${winningsId}`, + ); } } result.data = 'Successfully updated winnings'; + this.logger.info( + `updateWinnings completed for winningsId=${winningsId}: ${result.data}`, + ); } catch (error) { if ( error instanceof NotFoundException || error instanceof BadRequestException ) { + this.logger.warn( + `updateWinnings validation error for winningsId=${winningsId}: ${error.message}`, + ); throw error; } this.logger.error('Updating winnings failed', error); diff --git a/src/api/webhooks/trolley/handlers/tax-form.handler.ts b/src/api/webhooks/trolley/handlers/tax-form.handler.ts index 18ea555..085f332 100644 --- a/src/api/webhooks/trolley/handlers/tax-form.handler.ts +++ b/src/api/webhooks/trolley/handlers/tax-form.handler.ts @@ -63,6 +63,10 @@ export class TaxFormHandler { recipient: trolley_recipient, taxFormData: TaxFormStatusUpdatedEventData, ) { + this.logger.log( + `Processing tax form '${taxFormId}' for user '${recipient.user_id}' (recipient trolley id: '${recipient.trolley_id}')`, + ); + const existingFormAssociation = await this.prisma.user_tax_form_associations.findFirst({ where: { @@ -71,26 +75,45 @@ export class TaxFormHandler { }, }); + if (existingFormAssociation) { + this.logger.debug( + `Found existing association id='${existingFormAssociation.id}' status='${existingFormAssociation.tax_form_status}' date_filed='${existingFormAssociation.date_filed}'`, + ); + } else { + this.logger.debug('No existing tax form association found'); + } + const taxFormStatus = this.getTaxFormStatus( existingFormAssociation, taxFormData, ); + this.logger.log(`Determined tax form status: '${taxFormStatus}'`); // voided forms associations are removed from DB if ( taxFormData.status === TrolleyTaxFormStatus.Voided && existingFormAssociation ) { - return this.prisma.user_tax_form_associations.deleteMany({ + this.logger.log( + `Tax form '${taxFormId}' marked Voided — removing association(s) for user '${recipient.user_id}'`, + ); + const result = await this.prisma.user_tax_form_associations.deleteMany({ where: { user_id: recipient.user_id, tax_form_id: taxFormId, }, }); + this.logger.log( + `Deleted ${result.count ?? 0} association(s) for user '${recipient.user_id}' taxFormId '${taxFormId}'`, + ); + return result; } if (!existingFormAssociation) { - return this.prisma.user_tax_form_associations.create({ + this.logger.log( + `Creating tax form association for user '${recipient.user_id}' taxFormId '${taxFormId}'`, + ); + const created = await this.prisma.user_tax_form_associations.create({ data: { user_id: recipient.user_id, tax_form_status: taxFormStatus, @@ -98,15 +121,26 @@ export class TaxFormHandler { tax_form_id: taxFormId, }, }); + this.logger.log( + `Created association id='${created.id}' tax_form_status='${created.tax_form_status}'`, + ); + return created; } - return this.prisma.user_tax_form_associations.update({ - where: { id: existingFormAssociation?.id }, + this.logger.log( + `Updating association id='${existingFormAssociation.id}' for user '${recipient.user_id}'`, + ); + const updated = await this.prisma.user_tax_form_associations.update({ + where: { id: existingFormAssociation.id }, data: { tax_form_status: taxFormStatus, date_filed: taxFormData.signedAt, }, }); + this.logger.log( + `Updated association id='${updated.id}' tax_form_status='${updated.tax_form_status}'`, + ); + return updated; } /** diff --git a/src/shared/payments/payments.service.ts b/src/shared/payments/payments.service.ts index 3a49efc..047559b 100644 --- a/src/shared/payments/payments.service.ts +++ b/src/shared/payments/payments.service.ts @@ -3,9 +3,12 @@ import { JsonObject } from '@prisma/client/runtime/library'; import { PrismaService } from '../global/prisma.service'; import { payment_status, Prisma } from '@prisma/client'; import { uniq } from 'lodash'; +import { Logger } from 'src/shared/global'; @Injectable() export class PaymentsService { + private readonly logger = new Logger(PaymentsService.name); + constructor(private readonly prisma: PrismaService) {} /** @@ -95,14 +98,59 @@ export class PaymentsService { * This ensures that the payment statuses are accurately reflected in the system. */ async reconcileUserPayments(...userIds: string[]) { - const usersPayoutStatus = await this.getUsersPayoutStatus(userIds); + try { + const usersPayoutStatus = await this.getUsersPayoutStatus(userIds); + this.logger.debug( + `Reconciling payments for userIds=${JSON.stringify( + userIds, + )}; complete=${usersPayoutStatus.complete.length}; inProgress=${usersPayoutStatus.inProgress.length}`, + ); - if (usersPayoutStatus.complete.length) { - await this.toggleUserPaymentsStatus(usersPayoutStatus.complete, false); - } + if (usersPayoutStatus.complete.length) { + this.logger.info( + `Setting payments to OWED for users: ${usersPayoutStatus.complete.join( + ',', + )}`, + ); + await this.toggleUserPaymentsStatus(usersPayoutStatus.complete, false); + this.logger.debug( + `Payments set to OWED for users: ${usersPayoutStatus.complete.join( + ',', + )}`, + ); + } - if (usersPayoutStatus.inProgress.length) { - await this.toggleUserPaymentsStatus(usersPayoutStatus.inProgress, true); + if (usersPayoutStatus.inProgress.length) { + this.logger.info( + `Setting payments to ON_HOLD for users: ${usersPayoutStatus.inProgress.join( + ',', + )}`, + ); + await this.toggleUserPaymentsStatus(usersPayoutStatus.inProgress, true); + this.logger.debug( + `Payments set to ON_HOLD for users: ${usersPayoutStatus.inProgress.join( + ',', + )}`, + ); + } + + if ( + usersPayoutStatus.complete.length === 0 && + usersPayoutStatus.inProgress.length === 0 + ) { + this.logger.debug( + `No payment status changes required for userIds=${JSON.stringify( + userIds, + )}`, + ); + } + } catch (error) { + this.logger.error( + `Failed to reconcile payments for userIds=${JSON.stringify( + userIds, + )}: ${error?.message ?? error}`, + ); + throw error; } } From 3f35d39f8bd1ce1bb7d310929e07c4a420188212 Mon Sep 17 00:00:00 2001 From: Vasilica Olariu Date: Wed, 3 Dec 2025 19:18:52 +0200 Subject: [PATCH 2/2] use log instead of debug for logging --- src/api/admin/admin.service.ts | 26 +++++++++---------- .../trolley/handlers/tax-form.handler.ts | 4 +-- 2 files changed, 15 insertions(+), 15 deletions(-) diff --git a/src/api/admin/admin.service.ts b/src/api/admin/admin.service.ts index d558bf7..f723335 100644 --- a/src/api/admin/admin.service.ts +++ b/src/api/admin/admin.service.ts @@ -79,10 +79,10 @@ export class AdminService { let needsReconciliation = false; const winningsId = body.winningsId; - this.logger.info( + this.logger.log( `updateWinnings called by ${userId} for winningsId=${winningsId}`, ); - this.logger.debug(`updateWinnings payload: ${JSON.stringify(body)}`); + this.logger.log(`updateWinnings payload: ${JSON.stringify(body)}`); try { const payments = await this.getPaymentsByWinningsId( @@ -90,7 +90,7 @@ export class AdminService { body.paymentId, ); - this.logger.debug( + this.logger.log( `Found ${payments.length} payment(s) for winningsId=${winningsId}`, ); if (payments.length === 0) { @@ -103,7 +103,7 @@ export class AdminService { let releaseDate; if (body.paymentStatus) { releaseDate = await this.getPaymentReleaseDateByWinningsId(winningsId); - this.logger.debug( + this.logger.log( `Payment release date for winningsId=${winningsId}: ${releaseDate}`, ); } @@ -115,7 +115,7 @@ export class AdminService { // iterate payments and build transaction list payments.forEach((payment) => { - this.logger.debug( + this.logger.log( `Processing payment ${payment.payment_id} (installment ${payment.installment_number}) with current status=${payment.payment_status}`, ); @@ -246,7 +246,7 @@ export class AdminService { if (body.paymentStatus === PaymentStatus.OWED) { needsReconciliation = true; - this.logger.debug( + this.logger.log( `Payment ${payment.payment_id} marked OWED; will trigger reconciliation later`, ); } @@ -371,26 +371,26 @@ export class AdminService { } } - this.logger.debug( + this.logger.log( `Queued ${queuedActions.length} action(s) for payment ${payment.payment_id}: ${queuedActions.join( ' ; ', )}`, ); }); - this.logger.info( + this.logger.log( `Executing ${transactions.length} transaction step(s) for winningsId=${winningsId}`, ); // Run all transaction tasks in a single prisma transaction await this.prisma.$transaction(async (tx) => { for (let i = 0; i < transactions.length; i++) { - this.logger.debug(`Executing transaction ${i + 1}/${transactions.length}`); + this.logger.log(`Executing transaction ${i + 1}/${transactions.length}`); await transactions[i](tx); } }); - this.logger.info( + this.logger.log( `Successfully executed transactions for winningsId=${winningsId}`, ); @@ -405,11 +405,11 @@ export class AdminService { }); if (winning?.winner_id) { - this.logger.info( + this.logger.log( `Triggering payments reconciliation for user ${winning.winner_id}`, ); await this.paymentsService.reconcileUserPayments(winning.winner_id); - this.logger.info( + this.logger.log( `Reconciliation triggered for user ${winning.winner_id}`, ); } else { @@ -420,7 +420,7 @@ export class AdminService { } result.data = 'Successfully updated winnings'; - this.logger.info( + this.logger.log( `updateWinnings completed for winningsId=${winningsId}: ${result.data}`, ); } catch (error) { diff --git a/src/api/webhooks/trolley/handlers/tax-form.handler.ts b/src/api/webhooks/trolley/handlers/tax-form.handler.ts index 085f332..69fe58e 100644 --- a/src/api/webhooks/trolley/handlers/tax-form.handler.ts +++ b/src/api/webhooks/trolley/handlers/tax-form.handler.ts @@ -76,11 +76,11 @@ export class TaxFormHandler { }); if (existingFormAssociation) { - this.logger.debug( + this.logger.log( `Found existing association id='${existingFormAssociation.id}' status='${existingFormAssociation.tax_form_status}' date_filed='${existingFormAssociation.date_filed}'`, ); } else { - this.logger.debug('No existing tax form association found'); + this.logger.log('No existing tax form association found'); } const taxFormStatus = this.getTaxFormStatus(