From 018f9736090aadcf6aedda577751f4f419587fe3 Mon Sep 17 00:00:00 2001 From: mindesbunister Date: Sun, 16 Nov 2025 15:07:27 +0100 Subject: [PATCH] critical: Fix P&L compounding during close verification (20x inflation bug) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Problem: - Close transaction confirmed but Drift state takes 5-10s to propagate - Position Manager returned needsVerification=true to keep monitoring - BUT: Monitoring loop detected position as 'externally closed' EVERY 2 seconds - Each detection called handleExternalClosure() and added P&L to database - Result: .66 actual profit → 73.36 in database (20x compounding) - Logs showed: $112.96 → $117.62 → $122.28 → ... → $173.36 (14+ updates) Root Cause: - Common Pitfall #47 fix introduced needsVerification flag to wait for propagation - But NO flag to prevent external closure detection during wait period - Monitoring loop thought position was 'closed externally' on every cycle - Rate limiting (429 errors) made it worse by extending wait time Fix (closingInProgress flag): 1. Added closingInProgress boolean to ActiveTrade interface 2. Set flag=true when needsVerification returned (close confirmed, waiting) 3. Skip external closure detection entirely while flag=true 4. Timeout after 60s if stuck (abnormal case - allows cleanup) Impact: - Every close with verification delay (most closes) had 10-20x P&L inflation - This is variant of Common Pitfall #27 but during verification, not external closure - Rate limited closes were hit hardest (longer wait = more compounding cycles) Files: - lib/trading/position-manager.ts: Added closingInProgress flag + skip logic Incident: Nov 16, 11:50 CET - SHORT 41.64→40.08 showed 73.36 vs .66 real Documented: Common Pitfall #48 --- .github/copilot-instructions.md | 59 +++++++++++++++++++++++++++++++++ lib/trading/position-manager.ts | 51 ++++++++++++++++++++++------ 2 files changed, 100 insertions(+), 10 deletions(-) diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index 8d5839c..700f018 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -2064,6 +2064,65 @@ trade.realizedPnL += actualRealizedPnL // NOT: result.realizedPnL from SDK ``` - **Lesson:** In DEX trading, always verify state changes actually propagated before updating local state. ALWAYS verify container restart timestamp matches or exceeds commit timestamps before declaring fixes deployed. +48. **P&L compounding during close verification (CRITICAL - Fixed Nov 16, 2025):** + - **Symptom:** Database P&L shows $173.36 when actual P&L was $8.66 (20× too high) + - **Root Cause:** Variant of Common Pitfall #27 - duplicate external closure detection during close verification wait + - **Real incident (Nov 16, 11:50 CET):** + * SHORT position: Entry $141.64 → Exit $140.08 (expected P&L: $8.66) + * Close transaction confirmed, Drift verification pending (5-10s propagation delay) + * Position Manager returned with `needsVerification: true` flag + * **Every 2 seconds:** Monitoring loop checked Drift, saw position "missing", called `handleExternalClosure()` + * **Each call added P&L:** $112.96 → $117.62 → $122.28 → ... → $173.36 (14+ compounding updates) + * Rate limiting made it worse (429 errors delayed final cleanup) + - **Why it happened:** + * Fix #47 introduced `needsVerification` flag to keep monitoring during propagation delay + * BUT: No flag to prevent external closure detection during this wait period + * Monitoring loop thought position was "closed externally" every cycle + * Each detection calculated P&L and updated database, compounding the value + - **Impact:** Every close with verification delay (most closes) vulnerable to 10-20× P&L inflation + - **Fix (closingInProgress flag):** + ```typescript + // In ActiveTrade interface (line ~15): + // Close verification tracking (Nov 16, 2025) + closingInProgress?: boolean // True when close tx confirmed but Drift not yet propagated + closeConfirmedAt?: number // Timestamp when close was confirmed (for timeout) + + // In executeExit() when needsVerification returned (line ~1210): + if ((result as any).needsVerification) { + // CRITICAL: Mark as "closing in progress" to prevent duplicate external closure detection + trade.closingInProgress = true + trade.closeConfirmedAt = Date.now() + console.log(`🔒 Marked as closing in progress - external closure detection disabled`) + return + } + + // In monitoring loop BEFORE external closure check (line ~640): + if (trade.closingInProgress) { + const timeInClosing = Date.now() - (trade.closeConfirmedAt || Date.now()) + if (timeInClosing > 60000) { + // Stuck >60s (abnormal) - allow cleanup + trade.closingInProgress = false + } else { + // Normal: Skip external closure detection entirely during propagation wait + console.log(`🔒 Close in progress (${(timeInClosing / 1000).toFixed(0)}s) - skipping external closure check`) + } + } + + // External closure check only runs if NOT closingInProgress + if ((position === null || position.size === 0) && !trade.closingInProgress) { + // ... handle external closure + } + ``` + - **Behavior now:** + * Close confirmed → Set `closingInProgress = true` + * Monitoring continues but SKIPS external closure detection + * After 5-10s: Drift propagates, ghost detection cleans up correctly (one time only) + * If stuck >60s: Timeout allows cleanup (abnormal case) + - **Prevents:** Duplicate P&L updates during the 5-10s verification window + - **Related to:** Common Pitfall #27 (external closure duplicates), but different trigger + - **Files changed:** `lib/trading/position-manager.ts` (interface + logic) + - **Lesson:** When introducing wait periods in financial systems, always add flags to prevent duplicate state updates during the wait + 46. **100% position sizing causes InsufficientCollateral (Fixed Nov 16, 2025):** - **Symptom:** Bot configured for 100% position size gets InsufficientCollateral errors, but Drift UI can open same size position - **Root Cause:** Drift's margin calculation includes fees, slippage buffers, and rounding - exact 100% leaves no room diff --git a/lib/trading/position-manager.ts b/lib/trading/position-manager.ts index 47f4f4b..aaa7cf5 100644 --- a/lib/trading/position-manager.ts +++ b/lib/trading/position-manager.ts @@ -55,6 +55,10 @@ export interface ActiveTrade { timesScaled?: number // How many times position has been scaled totalScaleAdded?: number // Total USD added through scaling + // Close verification tracking (Nov 16, 2025) + closingInProgress?: boolean // True when close tx confirmed but Drift not yet propagated + closeConfirmedAt?: number // Timestamp when close was confirmed (for timeout) + // Monitoring priceCheckCount: number lastPrice: number @@ -633,7 +637,23 @@ export class PositionManager { } } - if (position === null || position.size === 0) { + // CRITICAL: Skip external closure detection if close is already in progress (Nov 16, 2025) + // This prevents duplicate P&L compounding when close tx confirmed but Drift not yet propagated + if (trade.closingInProgress) { + // Check if close has been stuck for >60 seconds (abnormal) + const timeInClosing = Date.now() - (trade.closeConfirmedAt || Date.now()) + if (timeInClosing > 60000) { + console.log(`⚠️ Close stuck in progress for ${(timeInClosing / 1000).toFixed(0)}s - allowing external closure check`) + trade.closingInProgress = false // Reset flag to allow cleanup + } else { + // Normal case: Close confirmed recently, waiting for Drift propagation (5-10s) + // Skip external closure detection entirely to prevent duplicate P&L updates + console.log(`🔒 Close in progress (${(timeInClosing / 1000).toFixed(0)}s) - skipping external closure check`) + // Continue to price calculations below (monitoring continues normally) + } + } + + if ((position === null || position.size === 0) && !trade.closingInProgress) { // CRITICAL: Use original position size for P&L calculation on external closures // trade.currentSize may already be 0 if on-chain orders closed the position before @@ -745,16 +765,18 @@ export class PositionManager { return } - // CRITICAL: Convert position.size (base asset tokens) to USD for comparison - const positionSizeUSD = Math.abs(position.size) * currentPrice - - // Position exists but size mismatch (partial close by TP1?) - if (positionSizeUSD < trade.currentSize * 0.95) { // 5% tolerance - console.log(`⚠️ Position size mismatch: expected $${trade.currentSize.toFixed(2)}, got $${positionSizeUSD.toFixed(2)}`) + // Position still exists on Drift - check for size mismatches + if (position && position.size !== 0 && !trade.closingInProgress) { + // CRITICAL: Convert position.size (base asset tokens) to USD for comparison + const positionSizeUSD = Math.abs(position.size) * currentPrice - // CRITICAL: Check if position direction changed (signal flip, not TP1!) - const positionDirection = position.side === 'long' ? 'long' : 'short' - if (positionDirection !== trade.direction) { + // Position exists but size mismatch (partial close by TP1?) + if (positionSizeUSD < trade.currentSize * 0.95) { // 5% tolerance + console.log(`⚠️ Position size mismatch: expected $${trade.currentSize.toFixed(2)}, got $${positionSizeUSD.toFixed(2)}`) + + // CRITICAL: Check if position direction changed (signal flip, not TP1!) + const positionDirection = position.side === 'long' ? 'long' : 'short' + if (positionDirection !== trade.direction) { console.log(`🔄 DIRECTION CHANGE DETECTED: ${trade.direction} → ${positionDirection}`) console.log(` This is a signal flip, not TP1! Closing old position as manual.`) @@ -825,6 +847,7 @@ export class PositionManager { trade.tp1Hit = true await this.saveTradeState(trade) } + } // End of: if (position && position.size !== 0 && !trade.closingInProgress) } catch (error) { // If we can't check position, continue with monitoring (don't want to false-positive) @@ -1210,6 +1233,14 @@ export class PositionManager { console.log(`⚠️ Close transaction confirmed but position still exists on Drift`) console.log(` Keeping ${trade.symbol} in monitoring until Drift confirms closure`) console.log(` Ghost detection will handle final cleanup once Drift updates`) + + // CRITICAL: Mark as "closing in progress" to prevent duplicate external closure detection + // Without this flag, the monitoring loop detects position as "externally closed" + // every 2 seconds and adds P&L repeatedly, causing 20x compounding bug + trade.closingInProgress = true + trade.closeConfirmedAt = Date.now() + console.log(`🔒 Marked as closing in progress - external closure detection disabled`) + // Keep monitoring - ghost detection will eventually see it's closed return }