diff --git a/contract/contracts/hello-world/src/autoshare_logic.rs b/contract/contracts/hello-world/src/autoshare_logic.rs index 951aa3c..d392945 100644 --- a/contract/contracts/hello-world/src/autoshare_logic.rs +++ b/contract/contracts/hello-world/src/autoshare_logic.rs @@ -1,8 +1,7 @@ use crate::base::errors::Error; use crate::base::events::{ - AdminTransferred, AuthorizationFailure, AutoshareCreated, AutoshareUpdated, - ContractPaused, ContractUnpaused, GroupActivated, GroupDeactivated, - NotificationCategory, Withdrawal, + AdminTransferred, AuthorizationFailure, AutoshareCreated, AutoshareUpdated, ContractPaused, + ContractUnpaused, GroupActivated, GroupDeactivated, NotificationCategory, Withdrawal, }; use crate::base::types::{AutoShareDetails, GroupMember, PaymentHistory}; use soroban_sdk::{contracttype, token, Address, BytesN, Env, String, Vec}; diff --git a/listener/.env.example b/listener/.env.example index a79b471..8c4461c 100644 --- a/listener/.env.example +++ b/listener/.env.example @@ -1,3 +1,7 @@ +# Logging Configuration +LOG_LEVEL=info +# NODE_ENV=production # Uncomment for newline-delimited JSON log output + # Stellar Network Configuration STELLAR_NETWORK=testnet STELLAR_RPC_URL=https://soroban-testnet.stellar.org:443 diff --git a/listener/LOGGING.md b/listener/LOGGING.md index 6adbe24..2b00634 100644 --- a/listener/LOGGING.md +++ b/listener/LOGGING.md @@ -47,6 +47,24 @@ The following messages mark each stage of the notification pipeline: | API request done | `info` | `GET /api/events complete` | | Reconnect attempt | `warn` | `Attempting to reconnect` | | Max retries exceeded | `error` | `Max reconnection attempts exceeded, stopping service`| +| Scheduler batch start | `info` | `Processing batch of scheduled notifications` | +| Scheduler batch done | `info` | `Scheduler batch complete` | +| Scheduled notification | `info` | `Processing scheduled notification` | +| Registry at capacity | `warn` | `Event registry at capacity, evicting oldest events` | + +## Error Formatting + +Errors passed in the `error` metadata field are automatically normalized into a structured object with `message`, `name`, `stack`, and optional `cause` fields. Use the exported `formatError()` helper when formatting errors outside the logger. + +```typescript +import logger, { formatError } from '../utils/logger'; + +try { + await deliverNotification(); +} catch (error) { + logger.error('Delivery failed', { requestId, error }); +} +``` ## Configuration diff --git a/listener/src/examples/schedule-notification-example.ts b/listener/src/examples/schedule-notification-example.ts index 6c8d05d..b08f299 100644 --- a/listener/src/examples/schedule-notification-example.ts +++ b/listener/src/examples/schedule-notification-example.ts @@ -1,6 +1,6 @@ /** * Example: How to schedule notifications - * + * * This file demonstrates various ways to schedule notifications * for future delivery using the NotificationAPI */ @@ -9,6 +9,7 @@ import { NotificationAPI } from '../services/notification-api'; import { ScheduledNotificationRepository } from '../services/scheduled-notification-repository'; import { initializeDatabase } from '../database/database'; import { NotificationType } from '../types/scheduled-notification'; +import logger from '../utils/logger'; async function examples() { // Initialize database and API @@ -37,7 +38,7 @@ async function examples() { oneHourLater ); - console.log(`Scheduled notification ID: ${notification1}`); + logger.info('Scheduled notification created', { id: notification1 }); // ==================================================================== // Example 2: Schedule a high-priority notification for tomorrow 9 AM @@ -69,7 +70,7 @@ async function examples() { }, }); - console.log(`High-priority notification scheduled for ${tomorrow9AM}`); + logger.info('High-priority notification scheduled', { executeAt: tomorrow9AM }); // ==================================================================== // Example 3: Schedule multiple notifications (batch scheduling) @@ -89,13 +90,13 @@ async function examples() { scheduleIds.push(id); } - console.log(`Scheduled ${scheduleIds.length} reminder notifications`); + logger.info('Batch reminder notifications scheduled', { count: scheduleIds.length }); // ==================================================================== // Example 4: Cancel a scheduled notification // ==================================================================== const cancelled = await api.cancelNotification(notification1); - console.log(`Notification ${notification1} cancelled: ${cancelled}`); + logger.info('Notification cancellation result', { id: notification1, cancelled }); // ==================================================================== // Example 5: Check notification status @@ -103,7 +104,7 @@ async function examples() { const notification = await api.getNotification(notification2); if (notification) { - console.log('Notification details:', { + logger.info('Notification details', { id: notification.id, status: notification.status, executeAt: notification.executeAt, @@ -116,8 +117,7 @@ async function examples() { // Example 6: Get scheduler statistics // ==================================================================== const stats = await api.getStatistics(); - console.log('Scheduler statistics:', stats); - // Output: { pending: 10, processing: 2, completed: 100, failed: 5, overdue: 1 } + logger.info('Scheduler statistics', stats); // ==================================================================== // Example 7: Schedule notification based on blockchain event @@ -154,7 +154,10 @@ async function examples() { }; const scheduledEventNotification = await scheduleEventNotification(mockEvent, 30); - console.log(`Event notification scheduled for 30 minutes: ${scheduledEventNotification}`); + logger.info('Event notification scheduled', { + id: scheduledEventNotification, + delayMinutes: 30, + }); // ==================================================================== // Example 8: Schedule with custom retry configuration @@ -172,7 +175,7 @@ async function examples() { }, }); - console.log(`Critical notification scheduled: ${criticalNotification}`); + logger.info('Critical notification scheduled', { id: criticalNotification }); // Clean up await db.close(); @@ -182,11 +185,11 @@ async function examples() { if (require.main === module) { examples() .then(() => { - console.log('Examples completed successfully'); + logger.info('Examples completed successfully'); process.exit(0); }) .catch((error) => { - console.error('Examples failed:', error); + logger.error('Examples failed', { error }); process.exit(1); }); } diff --git a/listener/src/services/discord-notification.ts b/listener/src/services/discord-notification.ts index 2c764ff..750b47f 100644 --- a/listener/src/services/discord-notification.ts +++ b/listener/src/services/discord-notification.ts @@ -81,10 +81,6 @@ export class DiscordNotificationService { } this.deduplicator.markSent(fingerprint); - logger.info('Discord notification sent successfully', { - eventId: event.id, - contractAddress: contractConfig.address, - }); logger.info('Discord notification delivered', { ...logContext, durationMs, diff --git a/listener/src/services/notification-api.ts b/listener/src/services/notification-api.ts index b310d2c..0671201 100644 --- a/listener/src/services/notification-api.ts +++ b/listener/src/services/notification-api.ts @@ -12,7 +12,10 @@ export class NotificationAPI { /** * Schedule a notification for future delivery */ - async scheduleNotification(input: CreateScheduledNotificationInput): Promise { + async scheduleNotification( + input: CreateScheduledNotificationInput, + requestId?: string + ): Promise { // Validate input if (!input.executeAt || input.executeAt < new Date()) { throw new Error('executeAt must be a future date'); @@ -27,12 +30,13 @@ export class NotificationAPI { } logger.info('Scheduling new notification', { + requestId, type: input.notificationType, executeAt: input.executeAt, recipient: input.targetRecipient, }); - return await this.repository.create(input); + return await this.repository.create(input, requestId); } /** @@ -62,8 +66,8 @@ export class NotificationAPI { /** * Cancel a scheduled notification */ - async cancelNotification(id: number): Promise { - logger.info('Cancelling scheduled notification', { id }); + async cancelNotification(id: number, requestId?: string): Promise { + logger.info('Cancelling scheduled notification', { requestId, id }); return await this.repository.cancel(id); } diff --git a/listener/src/services/notification-scheduler.ts b/listener/src/services/notification-scheduler.ts index 99157d2..4b36704 100644 --- a/listener/src/services/notification-scheduler.ts +++ b/listener/src/services/notification-scheduler.ts @@ -1,5 +1,6 @@ import { v4 as uuidv4 } from 'uuid'; import logger from '../utils/logger'; +import { generateRequestId } from '../utils/request-id'; import { ScheduledNotificationRepository } from './scheduled-notification-repository'; import { SchedulerConfig, NotificationStatus, ScheduledNotification } from '../types/scheduled-notification'; import { DiscordNotificationService } from './discord-notification'; @@ -92,44 +93,71 @@ export class NotificationScheduler { * Main processing loop */ private async processPendingNotifications(): Promise { + const requestId = generateRequestId(); + const batchStart = Date.now(); + try { // Recover any stale locks from crashed processors - await this.repository.recoverStaleLocks(); + await this.repository.recoverStaleLocks(requestId); // Fetch and lock pending notifications const notifications = await this.repository.fetchAndLockPendingNotifications( this.processorId, this.config.lockTimeoutMs, - this.config.batchSize + this.config.batchSize, + requestId ); if (notifications.length === 0) { + logger.debug('Scheduler poll cycle complete', { + requestId, + processorId: this.processorId, + count: 0, + durationMs: Date.now() - batchStart, + }); return; } logger.info('Processing batch of scheduled notifications', { + requestId, count: notifications.length, processorId: this.processorId, }); // Process each notification for (const notification of notifications) { - await this.processNotification(notification); + await this.processNotification(notification, requestId); } + + logger.info('Scheduler batch complete', { + requestId, + processorId: this.processorId, + count: notifications.length, + durationMs: Date.now() - batchStart, + }); } catch (error) { - logger.error('Error in scheduler processing loop', { error, processorId: this.processorId }); + logger.error('Error in scheduler processing loop', { + requestId, + error, + processorId: this.processorId, + durationMs: Date.now() - batchStart, + }); } } /** * Process a single notification */ - private async processNotification(notification: ScheduledNotification): Promise { + private async processNotification( + notification: ScheduledNotification, + requestId: string + ): Promise { const startTime = Date.now(); const executionAttempt = notification.retryCount + 1; try { logger.info('Processing scheduled notification', { + requestId, id: notification.id, type: notification.notificationType, executeAt: notification.executeAt, @@ -143,6 +171,7 @@ export class NotificationScheduler { if (timeDiff < -this.config.timingBufferMs) { // Notification is not yet due (clock skew or early fetch) logger.warn('Notification not yet due, releasing lock', { + requestId, id: notification.id, executeAt: notification.executeAt, now, @@ -157,35 +186,37 @@ export class NotificationScheduler { } // Execute notification based on type - const success = await this.executeNotification(notification); + const success = await this.executeNotification(notification, requestId); - const duration = Date.now() - startTime; + const durationMs = Date.now() - startTime; if (success) { - await this.repository.markAsCompleted(notification.id!); + await this.repository.markAsCompleted(notification.id!, requestId); await this.repository.logExecution({ scheduledNotificationId: notification.id!, executionAttempt, executionTime: new Date(), status: 'SUCCESS', - durationMs: duration, + durationMs, }); logger.info('Notification delivered successfully', { + requestId, id: notification.id, type: notification.notificationType, - duration, + durationMs, }); } else { throw new Error('Notification delivery returned false'); } } catch (error) { - const duration = Date.now() - startTime; + const durationMs = Date.now() - startTime; logger.error('Failed to process notification', { + requestId, id: notification.id, error, attempt: executionAttempt, - duration, + durationMs, }); await this.repository.markAsFailedOrRetry( @@ -201,7 +232,7 @@ export class NotificationScheduler { executionTime: new Date(), status: notification.retryCount >= notification.maxRetries ? 'FAILED' : 'RETRY', errorMessage: (error as Error).message, - durationMs: duration, + durationMs, }); } } @@ -209,7 +240,10 @@ export class NotificationScheduler { /** * Execute notification delivery based on type */ - private async executeNotification(notification: ScheduledNotification): Promise { + private async executeNotification( + notification: ScheduledNotification, + requestId: string + ): Promise { const payload = JSON.parse(notification.payload); switch (notification.notificationType) { @@ -220,7 +254,7 @@ export class NotificationScheduler { return await this.discordService.sendEventNotification( payload.event, payload.contractConfig, - `scheduler-${notification.id}` + `scheduler-${notification.id}-${requestId}` ); case 'webhook': diff --git a/listener/src/services/scheduled-notification-repository.ts b/listener/src/services/scheduled-notification-repository.ts index fc63896..b326707 100644 --- a/listener/src/services/scheduled-notification-repository.ts +++ b/listener/src/services/scheduled-notification-repository.ts @@ -18,7 +18,7 @@ export class ScheduledNotificationRepository { /** * Create a new scheduled notification */ - async create(input: CreateScheduledNotificationInput): Promise { + async create(input: CreateScheduledNotificationInput, requestId?: string): Promise { const sql = ` INSERT INTO scheduled_notifications ( payload, notification_type, target_recipient, execute_at, @@ -40,6 +40,7 @@ export class ScheduledNotificationRepository { const result = await this.db.run(sql, params); logger.info('Scheduled notification created', { + requestId, id: result.lastID, executeAt: input.executeAt, type: input.notificationType, @@ -55,7 +56,8 @@ export class ScheduledNotificationRepository { async fetchAndLockPendingNotifications( processorId: string, lockTimeoutMs: number, - batchSize: number = 10 + batchSize: number = 10, + requestId?: string ): Promise { const now = new Date(); const lockExpiresAt = new Date(now.getTime() + lockTimeoutMs); @@ -106,6 +108,7 @@ export class ScheduledNotificationRepository { ]); logger.info('Fetched and locked pending notifications', { + requestId, count: rows.length, processorId, }); @@ -117,7 +120,7 @@ export class ScheduledNotificationRepository { * Recover stale locks (when a processor crashes) * Returns notifications with expired locks back to PENDING */ - async recoverStaleLocks(): Promise { + async recoverStaleLocks(requestId?: string): Promise { const now = new Date(); const sql = ` @@ -138,7 +141,7 @@ export class ScheduledNotificationRepository { ]); if (result.changes > 0) { - logger.warn('Recovered stale locks', { count: result.changes }); + logger.warn('Recovered stale locks', { requestId, count: result.changes }); } return result.changes; @@ -147,7 +150,7 @@ export class ScheduledNotificationRepository { /** * Mark notification as completed */ - async markAsCompleted(id: number): Promise { + async markAsCompleted(id: number, requestId?: string): Promise { const sql = ` UPDATE scheduled_notifications SET @@ -164,7 +167,7 @@ export class ScheduledNotificationRepository { id, ]); - logger.info('Notification marked as completed', { id }); + logger.info('Notification marked as completed', { requestId, id }); } /** diff --git a/listener/src/store/event-registry.test.ts b/listener/src/store/event-registry.test.ts index 7be4c21..67672bb 100644 --- a/listener/src/store/event-registry.test.ts +++ b/listener/src/store/event-registry.test.ts @@ -1,6 +1,20 @@ import { xdr } from '@stellar/stellar-sdk'; import { EventRegistry } from './event-registry'; +jest.mock('../utils/logger', () => ({ + __esModule: true, + default: { + debug: jest.fn(), + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + }, +})); + +import logger from '../utils/logger'; + +const mockedLogger = logger as jest.Mocked; + describe('EventRegistry', () => { it('stores and returns display events from registry input', () => { const registry = new EventRegistry(5); @@ -65,5 +79,10 @@ describe('EventRegistry', () => { expect(events).toHaveLength(3); expect(events[0].eventId).toBe('evt-2'); expect(events[2].eventId).toBe('evt-4'); + expect(mockedLogger.warn).toHaveBeenCalledWith( + 'Event registry at capacity, evicting oldest events', + expect.objectContaining({ maxEvents: 3, evicted: 1 }) + ); + expect(mockedLogger.warn).toHaveBeenCalledTimes(2); }); }); diff --git a/listener/src/store/event-registry.ts b/listener/src/store/event-registry.ts index e1bda12..a3b47c1 100644 --- a/listener/src/store/event-registry.ts +++ b/listener/src/store/event-registry.ts @@ -1,6 +1,7 @@ import { DisplayEvent } from '../types/display-event'; import { RegistryEventInput } from '../types/registry-event-input'; import { formatScValArray, formatScValValue } from '../utils/scval-format'; +import logger from '../utils/logger'; const DEFAULT_MAX_EVENTS = 10000; @@ -29,7 +30,12 @@ export class EventRegistry { this.events.push(displayEvent); if (this.events.length > this.maxEvents) { + const evicted = this.events.length - this.maxEvents; this.events = this.events.slice(this.events.length - this.maxEvents); + logger.warn('Event registry at capacity, evicting oldest events', { + maxEvents: this.maxEvents, + evicted, + }); } return displayEvent; diff --git a/listener/src/utils/logger.test.ts b/listener/src/utils/logger.test.ts new file mode 100644 index 0000000..bda74e3 --- /dev/null +++ b/listener/src/utils/logger.test.ts @@ -0,0 +1,34 @@ +import { formatError } from './logger'; + +describe('formatError', () => { + it('formats Error instances with message, name, and stack', () => { + const error = new Error('Something went wrong'); + const formatted = formatError(error); + + expect(formatted).toMatchObject({ + message: 'Something went wrong', + name: 'Error', + stack: expect.any(String), + }); + }); + + it('formats nested error causes', () => { + const cause = new Error('Root cause'); + const error = new Error('Wrapper error'); + (error as Error & { cause: Error }).cause = cause; + const formatted = formatError(error); + + expect(formatted).toMatchObject({ + message: 'Wrapper error', + cause: { + message: 'Root cause', + name: 'Error', + }, + }); + }); + + it('stringifies non-error values', () => { + expect(formatError('plain string')).toBe('plain string'); + expect(formatError(404)).toBe('404'); + }); +}); diff --git a/listener/src/utils/logger.ts b/listener/src/utils/logger.ts index 1751307..e7ed62f 100644 --- a/listener/src/utils/logger.ts +++ b/listener/src/utils/logger.ts @@ -1,18 +1,80 @@ import winston from 'winston'; +export interface FormattedError { + message: string; + name: string; + stack?: string; + cause?: FormattedError | string; +} + +/** + * Normalize unknown thrown values into a structured object for logging. + */ +export function formatError(error: unknown): FormattedError | string { + if (error instanceof Error) { + const formatted: FormattedError = { + message: error.message, + name: error.name, + }; + + if (error.stack) { + formatted.stack = error.stack; + } + + if ('cause' in error && error.cause !== undefined) { + formatted.cause = formatError(error.cause); + } + + return formatted; + } + + if (typeof error === 'object' && error !== null) { + try { + return JSON.stringify(error); + } catch { + return String(error); + } + } + + return String(error); +} + +function formatMeta(meta: Record): Record { + if (!('error' in meta) || meta.error === undefined) { + return meta; + } + + return { + ...meta, + error: formatError(meta.error), + }; +} + +function logWithMeta( + level: 'debug' | 'info' | 'warn' | 'error', + message: string, + meta?: Record +): void { + if (meta && Object.keys(meta).length > 0) { + baseLogger[level](message, formatMeta(meta)); + } else { + baseLogger[level](message); + } +} + /** * Structured logger for the notification pipeline. * * All log entries include: * - timestamp – ISO 8601 timestamp - * - level – log severity (info, warn, error, debug) + * - level – log severity (debug, info, warn, error) * - message – human-readable description of the event * - requestId – (optional) identifier propagated through a poll/request cycle * - durationMs – (optional) elapsed time for timed operations * * Set LOG_LEVEL env var to control verbosity (default: "info"). */ -const logger = winston.createLogger({ +const baseLogger = winston.createLogger({ level: process.env.LOG_LEVEL || 'info', format: winston.format.combine( winston.format.timestamp(), @@ -35,4 +97,11 @@ const logger = winston.createLogger({ ], }); +const logger = { + debug: (message: string, meta?: Record) => logWithMeta('debug', message, meta), + info: (message: string, meta?: Record) => logWithMeta('info', message, meta), + warn: (message: string, meta?: Record) => logWithMeta('warn', message, meta), + error: (message: string, meta?: Record) => logWithMeta('error', message, meta), +}; + export default logger; diff --git a/listener/test-sdk.ts b/listener/test-sdk.ts index 8e0cb72..89c4b2a 100644 --- a/listener/test-sdk.ts +++ b/listener/test-sdk.ts @@ -1,4 +1,7 @@ import * as StellarSDK from '@stellar/stellar-sdk'; -console.log("StellarSDK.rpc keys:", Object.keys(StellarSDK.rpc)); -console.log("\nStellarSDK.rpc.Server methods:", Object.getOwnPropertyNames(StellarSDK.rpc.Server.prototype)); +import logger from './src/utils/logger'; +logger.info('StellarSDK.rpc keys', { keys: Object.keys(StellarSDK.rpc) }); +logger.info('StellarSDK.rpc.Server methods', { + methods: Object.getOwnPropertyNames(StellarSDK.rpc.Server.prototype), +});