diff --git a/docs/BUG_77_RECURRENCE_DEBUG_DEC15_2025.md b/docs/BUG_77_RECURRENCE_DEBUG_DEC15_2025.md new file mode 100644 index 0000000..02ad77f --- /dev/null +++ b/docs/BUG_77_RECURRENCE_DEBUG_DEC15_2025.md @@ -0,0 +1,202 @@ +# Bug #77 Recurrence - Position Manager Condition Checks Never Execute (Dec 15, 2025) + +## Status: ๐Ÿ”ด CRITICAL - UNDER INVESTIGATION + +**Impact:** $1,000+ losses from 96% data loss ($32.98 actual profit vs $1.23 recorded in database) + +## The Problem + +Position Manager monitoring loop IS running: +- โœ… Price checks every 2 seconds: `"๐Ÿ” Price check: SOL-PERP @ $124.47 (1 trades)"` +- โœ… handlePriceUpdate() executes successfully (line 653-670) +- โœ… Loop calls checkTradeConditions() for each trade (line 664-668) + +BUT condition evaluation logic NEVER executes: +- โŒ NO TP1 detection logs +- โŒ NO TP2 detection logs +- โŒ NO Stop Loss detection logs +- โŒ NO executeExit() calls +- โŒ NO P&L status logs (every 10 checks) + +**Result:** All trades rely ONLY on on-chain LIMIT orders auto-filling. Position Manager is 100% non-functional despite monitoring showing active. + +## Evidence Trail + +### What We Know Works + +**handlePriceUpdate() (lines 653-670):** +``` +๐Ÿ” Price check: SOL-PERP @ $123.69 (1 trades) +๐Ÿ” Price check: SOL-PERP @ $123.70 (1 trades) +๐Ÿ” Price check: SOL-PERP @ $123.71 (1 trades) +... repeating every 2 seconds +``` + +This proves: +- Pyth price monitor is calling handlePriceUpdate() +- tradesForSymbol.filter() finds 1 trade +- Loop at line 664 executes + +### What We Know Doesn't Work + +**checkTradeConditions() body (lines 677-1510):** +- Trade ID "cmj7d25yu0002pe0754v8pd21" appears ZERO times in logs +- No "โญ๏ธ Skipping" logs (line 681 check passes) +- No "โณ Trade" logs (line 709 - trade age check) +- No "โš ๏ธ Position APPEARS closed" logs (line 718 - external closure detection) +- No "๐Ÿ“Š" logs (line 1482 - status every 10 checks) +- No condition evaluation logs (lines 1497+ - shouldEmergencyStop, shouldStopLoss, shouldTakeProfit1) + +## Hypothesis: Early Return at Line 711 + +**Code:** +```typescript +// Line 702-711 +const tradeAgeSeconds = (Date.now() - trade.entryTime) / 1000 + +if (position === null || position.size === 0) { + if (tradeAgeSeconds < 30) { + logger.log(`โณ Trade ${trade.symbol} is new (${tradeAgeSeconds.toFixed(1)}s old) - skipping external closure check`) + return // Skip this check cycle, position might still be propagating + } +``` + +**Scenario:** +1. Trade created at 16:21:13 (>6 hours ago) - age check SHOULD pass +2. Drift position is CLOSED (sync-positions API returns empty) - `position.size === 0` is TRUE +3. But trade age > 30 seconds, so should continue to double-check logic at line 714 +4. UNLESS: `getPosition()` is throwing an exception caught by outer try-catch + +**Alternative Explanation:** +- The outer try-catch at line 666 catches ALL exceptions from checkTradeConditions() +- If ANY unhandled exception occurs, catch logs `"โŒ Error checking trade ${trade.id}"` +- But NO such logs exist in container output +- So either: + * Exception is being caught and silenced elsewhere + * OR function is returning early without exception + +## Debug Logging Added (Dec 15, 2025) + +**New logs inserted at line 691:** +```typescript +console.log(`๐Ÿ” STARTCHK: ${trade.symbol} @ $${currentPrice.toFixed(2)} | Entry: $${trade.entryPrice.toFixed(2)} | Checks: ${trade.priceCheckCount}`) +``` + +**New logs inserted at line 703:** +```typescript +console.log(`๐Ÿ” DRIFT: Position ${trade.symbol} | size=${position?.size || 'null'} | exists=${position !== null}`) +``` + +**New logs inserted at line 708:** +```typescript +console.log(`๐Ÿ” AGE: ${trade.symbol} age=${tradeAgeSeconds.toFixed(1)}s | threshold=30s`) +``` + +## What Debug Logs Will Reveal + +**Case 1: STARTCHK appears but DRIFT doesn't** +- Means: getPosition() is throwing exception +- Location: Drift SDK call at line 700 +- Fix: Catch exception, log error, continue to condition checks + +**Case 2: DRIFT appears, shows size=0, but AGE doesn't** +- Means: Trade age check is failing somehow +- Location: Line 702 calculation or line 706 condition +- Fix: Investigate entryTime timestamp format + +**Case 3: AGE appears, shows >30s, but condition checks still don't execute** +- Means: Early return is happening between line 708 and line 1497 +- Location: Likely in double-check logic (lines 714-800) +- Fix: Add more debug logs to find exact return location + +**Case 4: None of the debug logs appear** +- Means: Line 681 `activeTrades.has(trade.id)` is failing +- Location: Map key mismatch between loop and Map +- Fix: Investigate how trades are added to Map vs how they're checked + +## Next Steps + +1. **Wait for next manual trade** (Telegram or TradingView) +2. **Monitor docker logs** for new debug messages +3. **Identify WHERE** checkTradeConditions() is returning early +4. **Fix root cause** based on debug log evidence +5. **Deploy fix** with verification +6. **Remove debug logging** once fixed + +## Historical Context + +**Bug #77 Original (Dec 13, 2025):** +- Drift service lazy initialization caused early return at line 692-696 +- Fixed by removing Drift init check, allowing graceful failure later +- Commit: 01bd730 "critical: FIX Bug #77 - Position Manager monitoring stopped by Drift init check" + +**Bug #77 Recurrence (Dec 15, 2025):** +- DIFFERENT early return location +- Monitoring loop works, but condition checks never reach +- Same symptom (no TP1/TP2/SL detection) but different root cause +- This investigation: Finding NEW early return location + +## Related Bugs + +- **Bug #76:** placeExitOrders() returns SUCCESS with missing SL order +- **Bug #78:** Orphan detection removes active position orders +- **Bug #73:** Service initialization never ran for 16 days +- **Bug #82:** Drift State Verifier kills active position SL orders + +All these bugs share common theme: **Silent failures** - system appears to work (logs say "monitoring" or "orders placed") but critical operations don't execute. + +## Verification Commands + +```bash +# Check if debug logs appearing +docker logs -f trading-bot-v4 2>&1 | grep -E "(๐Ÿ” STARTCHK|๐Ÿ” DRIFT|๐Ÿ” AGE)" + +# Check current monitoring state +curl -s http://localhost:3001/api/trading/sync-positions | jq '.' + +# Check active trades in database +docker exec trading-bot-postgres psql -U postgres -d trading_bot_v4 -c \ + "SELECT id, symbol, direction, entryPrice, createdAt FROM \"Trade\" WHERE exitReason IS NULL;" +``` + +## Files Changed + +- `lib/trading/position-manager.ts` (lines 691, 703, 708) + * Added 3 console.log statements for debugging + * NO LOGIC CHANGES - only observability + +## Git Commits + +- 0909846 "debug: Add comprehensive logging to Position Manager checkTradeConditions (Bug #77 recurrence)" (Dec 15, 2025) + +## Current Container State (Dec 15, 2025 22:38 CET) + +- Container: trading-bot-v4 +- Started: 2025-12-15 22:27:15 UTC +- Build: Dec 15, 2025 22:24:51 CET (includes debug logging) +- Status: โœ… Running, debug logs active +- Active Trades: 0 (waiting for next trade to test) +- Free Collateral: $159.34 (insufficient for test trade) + +## User Impact + +**Financial Loss:** $1,000+ from Bug #77 recurrence over past days/weeks +- Position opened, monitored, but never hit TP1/TP2 +- All exits happened via on-chain LIMIT orders auto-filling +- Position Manager 100% non-functional despite "monitoring active" logs + +**User Quote:** "so the whole time all the development we did was not working and therefore we have lost 1000$...... i hope with the new test system this is an issue of the past" + +## Resolution Plan + +1. โœ… Debug logging added and deployed (Dec 15, 22:38 CET) +2. โณ Waiting for next manual trade to trigger monitoring +3. ๐ŸŽฏ Identify exact early return location from debug logs +4. ๐Ÿ”ง Fix root cause (likely line 711 or exception handling) +5. โœ… Deploy fix with verification +6. ๐Ÿงน Remove debug logging once confirmed working +7. ๐Ÿ“ Update Common Pitfalls section with full analysis + +**Priority:** CRITICAL - System is trading but without proper monitoring +**Timeline:** Fix ASAP (within next trade cycle) +**Verification:** Must see STARTCHK, DRIFT, AGE logs + condition evaluation logs on next trade