trading_bot_v4/docs/BUG_77_RECURRENCE_DEBUG_DEC15_2025.md

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:

// 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:

console.log(`🔍 STARTCHK: ${trade.symbol} @ $${currentPrice.toFixed(2)} | Entry: $${trade.entryPrice.toFixed(2)} | Checks: ${trade.priceCheckCount}`)

New logs inserted at line 703:

console.log(`🔍 DRIFT: Position ${trade.symbol} | size=${position?.size || 'null'} | exists=${position !== null}`)

New logs inserted at line 708:

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

# 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