346 lines
10 KiB
TypeScript
346 lines
10 KiB
TypeScript
/**
|
|
* Bug #80 Test: Retry Loop Cooldown Enforcement
|
|
*
|
|
* Tests that drift-state-verifier respects 5-minute cooldown and doesn't
|
|
* repeatedly retry closing positions, which strips protection.
|
|
*
|
|
* Created: Dec 9, 2025
|
|
* Reason: Bug #80 - Retry loop doesn't enforce cooldown properly
|
|
*/
|
|
|
|
import { getDriftStateVerifier } from '../../../lib/monitoring/drift-state-verifier'
|
|
|
|
// Mock dependencies
|
|
jest.mock('../../../lib/drift/client')
|
|
jest.mock('../../../lib/drift/orders')
|
|
jest.mock('../../../lib/database/trades', () => ({
|
|
getPrismaClient: jest.fn(),
|
|
}))
|
|
jest.mock('../../../lib/notifications/telegram')
|
|
|
|
describe('Bug #80: Retry Loop Cooldown', () => {
|
|
let verifier: any
|
|
let mockClosePosition: jest.Mock
|
|
let mockPrisma: any
|
|
|
|
beforeEach(() => {
|
|
jest.clearAllMocks()
|
|
|
|
// Get verifier instance
|
|
verifier = getDriftStateVerifier()
|
|
|
|
// Access private methods via type assertion for testing
|
|
verifier.recentCloseAttempts = new Map()
|
|
|
|
// Mock Drift service
|
|
const { getDriftService } = require('../../../lib/drift/client')
|
|
getDriftService.mockResolvedValue({
|
|
getPosition: jest.fn().mockResolvedValue({ size: 0, side: 'none' })
|
|
})
|
|
|
|
// Mock closePosition
|
|
const ordersModule = require('../../../lib/drift/orders')
|
|
mockClosePosition = ordersModule.closePosition
|
|
mockClosePosition.mockResolvedValue({
|
|
success: true,
|
|
transactionSignature: 'CLOSE_TX',
|
|
realizedPnL: -10.50
|
|
})
|
|
|
|
// Mock Prisma
|
|
const { getPrismaClient } = require('../../../lib/database/trades')
|
|
mockPrisma = {
|
|
trade: {
|
|
findUnique: jest.fn(),
|
|
findFirst: jest.fn().mockResolvedValue(null),
|
|
update: jest.fn()
|
|
}
|
|
}
|
|
getPrismaClient.mockReturnValue(mockPrisma)
|
|
})
|
|
|
|
describe('In-Memory Cooldown Map', () => {
|
|
it('should allow first close attempt', async () => {
|
|
const mismatch = {
|
|
tradeId: 'trade1',
|
|
symbol: 'SOL-PERP',
|
|
expectedState: 'closed' as const,
|
|
actualState: 'open' as const,
|
|
driftSize: 14.47,
|
|
dbExitReason: 'TP1',
|
|
timeSinceExit: 60000
|
|
}
|
|
|
|
mockPrisma.trade.findUnique.mockResolvedValue({
|
|
id: 'trade1',
|
|
configSnapshot: {}
|
|
})
|
|
|
|
await (verifier as any).retryClose(mismatch)
|
|
|
|
// Should have called closePosition
|
|
expect(mockClosePosition).toHaveBeenCalledWith({
|
|
symbol: 'SOL-PERP',
|
|
percentToClose: 100,
|
|
slippageTolerance: 0.05
|
|
})
|
|
|
|
// Should have recorded attempt in map
|
|
expect(verifier.recentCloseAttempts.has('SOL-PERP')).toBe(true)
|
|
})
|
|
|
|
it('should block retry within 5-minute cooldown', async () => {
|
|
const consoleSpy = jest.spyOn(console, 'log').mockImplementation()
|
|
|
|
const mismatch = {
|
|
tradeId: 'trade1',
|
|
symbol: 'SOL-PERP',
|
|
expectedState: 'closed' as const,
|
|
actualState: 'open' as const,
|
|
driftSize: 14.47,
|
|
dbExitReason: 'TP1',
|
|
timeSinceExit: 60000
|
|
}
|
|
|
|
// Set recent attempt (2 minutes ago)
|
|
const twoMinutesAgo = Date.now() - (2 * 60 * 1000)
|
|
verifier.recentCloseAttempts.set('SOL-PERP', twoMinutesAgo)
|
|
|
|
await (verifier as any).retryClose(mismatch)
|
|
|
|
// Should NOT have called closePosition
|
|
expect(mockClosePosition).not.toHaveBeenCalled()
|
|
|
|
// Should have logged cooldown message
|
|
expect(consoleSpy).toHaveBeenCalledWith(
|
|
expect.stringContaining('COOLDOWN ACTIVE')
|
|
)
|
|
|
|
consoleSpy.mockRestore()
|
|
})
|
|
|
|
it('should allow retry after cooldown expires (> 5 minutes)', async () => {
|
|
const mismatch = {
|
|
tradeId: 'trade1',
|
|
symbol: 'SOL-PERP',
|
|
expectedState: 'closed' as const,
|
|
actualState: 'open' as const,
|
|
driftSize: 14.47,
|
|
dbExitReason: 'TP1',
|
|
timeSinceExit: 60000
|
|
}
|
|
|
|
// Set old attempt (6 minutes ago - cooldown expired)
|
|
const sixMinutesAgo = Date.now() - (6 * 60 * 1000)
|
|
verifier.recentCloseAttempts.set('SOL-PERP', sixMinutesAgo)
|
|
|
|
mockPrisma.trade.findUnique.mockResolvedValue({
|
|
id: 'trade1',
|
|
configSnapshot: {}
|
|
})
|
|
|
|
await (verifier as any).retryClose(mismatch)
|
|
|
|
// Should have called closePosition (cooldown expired)
|
|
expect(mockClosePosition).toHaveBeenCalled()
|
|
})
|
|
|
|
it('should log remaining cooldown time', async () => {
|
|
const consoleSpy = jest.spyOn(console, 'log').mockImplementation()
|
|
|
|
const mismatch = {
|
|
tradeId: 'trade1',
|
|
symbol: 'SOL-PERP',
|
|
expectedState: 'closed' as const,
|
|
actualState: 'open' as const,
|
|
driftSize: 14.47,
|
|
dbExitReason: 'TP1',
|
|
timeSinceExit: 60000
|
|
}
|
|
|
|
// Set recent attempt (90 seconds ago)
|
|
const ninetySecondsAgo = Date.now() - (90 * 1000)
|
|
verifier.recentCloseAttempts.set('SOL-PERP', ninetySecondsAgo)
|
|
|
|
await (verifier as any).retryClose(mismatch)
|
|
|
|
// Should log remaining wait time
|
|
expect(consoleSpy).toHaveBeenCalledWith(
|
|
expect.stringMatching(/Must wait \d+s more/)
|
|
)
|
|
|
|
consoleSpy.mockRestore()
|
|
})
|
|
|
|
it('should log cooldown map state', async () => {
|
|
const consoleSpy = jest.spyOn(console, 'log').mockImplementation()
|
|
|
|
const mismatch = {
|
|
tradeId: 'trade1',
|
|
symbol: 'SOL-PERP',
|
|
expectedState: 'closed' as const,
|
|
actualState: 'open' as const,
|
|
driftSize: 14.47,
|
|
dbExitReason: 'TP1',
|
|
timeSinceExit: 60000
|
|
}
|
|
|
|
// Set recent attempts for multiple symbols
|
|
verifier.recentCloseAttempts.set('SOL-PERP', Date.now() - 30000)
|
|
verifier.recentCloseAttempts.set('ETH-PERP', Date.now() - 60000)
|
|
|
|
await (verifier as any).retryClose(mismatch)
|
|
|
|
// Should log map state
|
|
expect(consoleSpy).toHaveBeenCalledWith(
|
|
expect.stringContaining('Cooldown map state:')
|
|
)
|
|
|
|
consoleSpy.mockRestore()
|
|
})
|
|
})
|
|
|
|
describe('Database Cooldown Persistence', () => {
|
|
it('should check database for cooldown even if map is empty', async () => {
|
|
const mismatch = {
|
|
tradeId: 'trade1',
|
|
symbol: 'SOL-PERP',
|
|
expectedState: 'closed' as const,
|
|
actualState: 'open' as const,
|
|
driftSize: 14.47,
|
|
dbExitReason: 'TP1',
|
|
timeSinceExit: 60000
|
|
}
|
|
|
|
// Map is empty (simulates restart)
|
|
expect(verifier.recentCloseAttempts.size).toBe(0)
|
|
|
|
// But database has recent attempt
|
|
const twoMinutesAgo = new Date(Date.now() - (2 * 60 * 1000))
|
|
mockPrisma.trade.findFirst.mockResolvedValue({
|
|
configSnapshot: { retryCloseTime: twoMinutesAgo.toISOString() }
|
|
})
|
|
mockPrisma.trade.findUnique.mockResolvedValue({
|
|
id: 'trade1',
|
|
configSnapshot: {
|
|
retryCloseTime: twoMinutesAgo.toISOString()
|
|
}
|
|
})
|
|
|
|
await (verifier as any).retryClose(mismatch)
|
|
|
|
// Should NOT have called closePosition (DB cooldown active)
|
|
expect(mockClosePosition).not.toHaveBeenCalled()
|
|
})
|
|
|
|
it('should update in-memory map from database', async () => {
|
|
const mismatch = {
|
|
tradeId: 'trade1',
|
|
symbol: 'SOL-PERP',
|
|
expectedState: 'closed' as const,
|
|
actualState: 'open' as const,
|
|
driftSize: 14.47,
|
|
dbExitReason: 'TP1',
|
|
timeSinceExit: 60000
|
|
}
|
|
|
|
const oneMinuteAgo = new Date(Date.now() - (1 * 60 * 1000))
|
|
mockPrisma.trade.findUnique.mockResolvedValue({
|
|
id: 'trade1',
|
|
configSnapshot: {
|
|
retryCloseTime: oneMinuteAgo.toISOString()
|
|
}
|
|
})
|
|
mockPrisma.trade.findFirst.mockResolvedValue({
|
|
configSnapshot: { retryCloseTime: oneMinuteAgo.toISOString() }
|
|
})
|
|
|
|
await (verifier as any).retryClose(mismatch)
|
|
|
|
// Should have updated map from DB
|
|
expect(verifier.recentCloseAttempts.has('SOL-PERP')).toBe(true)
|
|
})
|
|
|
|
it('should persist attempt to database after successful close', async () => {
|
|
const mismatch = {
|
|
tradeId: 'trade1',
|
|
symbol: 'SOL-PERP',
|
|
expectedState: 'closed' as const,
|
|
actualState: 'open' as const,
|
|
driftSize: 14.47,
|
|
dbExitReason: 'TP1',
|
|
timeSinceExit: 60000
|
|
}
|
|
|
|
mockPrisma.trade.findUnique.mockResolvedValue({
|
|
id: 'trade1',
|
|
configSnapshot: {}
|
|
})
|
|
|
|
mockPrisma.trade.update.mockResolvedValue({})
|
|
|
|
await (verifier as any).retryClose(mismatch)
|
|
|
|
// Should have updated database with retry time
|
|
expect(mockPrisma.trade.update).toHaveBeenCalledWith({
|
|
where: { id: 'trade1' },
|
|
data: expect.objectContaining({
|
|
configSnapshot: expect.objectContaining({
|
|
retryCloseAttempted: true,
|
|
retryCloseTime: expect.any(String)
|
|
})
|
|
})
|
|
})
|
|
})
|
|
})
|
|
|
|
describe('Error Handling', () => {
|
|
it('should record attempt even on close failure to prevent spam', async () => {
|
|
const mismatch = {
|
|
tradeId: 'trade1',
|
|
symbol: 'SOL-PERP',
|
|
expectedState: 'closed' as const,
|
|
actualState: 'open' as const,
|
|
driftSize: 14.47,
|
|
dbExitReason: 'TP1',
|
|
timeSinceExit: 60000
|
|
}
|
|
|
|
mockPrisma.trade.findUnique.mockResolvedValue({
|
|
id: 'trade1',
|
|
configSnapshot: {}
|
|
})
|
|
|
|
// Close fails
|
|
mockClosePosition.mockResolvedValue({
|
|
success: false,
|
|
error: 'RPC timeout'
|
|
})
|
|
|
|
await (verifier as any).retryClose(mismatch)
|
|
|
|
// Should still have recorded attempt
|
|
expect(verifier.recentCloseAttempts.has('SOL-PERP')).toBe(true)
|
|
})
|
|
|
|
it('should record attempt on exception to prevent rapid retries', async () => {
|
|
const mismatch = {
|
|
tradeId: 'trade1',
|
|
symbol: 'SOL-PERP',
|
|
expectedState: 'closed' as const,
|
|
actualState: 'open' as const,
|
|
driftSize: 14.47,
|
|
dbExitReason: 'TP1',
|
|
timeSinceExit: 60000
|
|
}
|
|
|
|
mockPrisma.trade.findUnique.mockRejectedValue(new Error('Database error'))
|
|
|
|
await (verifier as any).retryClose(mismatch)
|
|
|
|
// Should have recorded attempt even on error
|
|
expect(verifier.recentCloseAttempts.has('SOL-PERP')).toBe(true)
|
|
})
|
|
})
|
|
})
|