docs: Bug #77 recurrence investigation summary
- Position Manager monitoring runs but condition checks never execute - Added 3 debug logs: STARTCHK, DRIFT, AGE to identify early return location - ,000+ losses from non-functional monitoring despite 'active' logs - Waiting for next trade to capture debug output and identify root cause - Related to previous Dec 13 fix (different early return location)
This commit is contained in:
mindesbunister
202
docs/BUG_77_RECURRENCE_DEBUG_DEC15_2025.md
Normal file
202
docs/BUG_77_RECURRENCE_DEBUG_DEC15_2025.md
Normal file
@@ -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
|
||||
Reference in New Issue
Block a user