Update fetch borkerPosition in bot + better HandleClosePosition + Add debug channel to receive all debug

This commit is contained in:
2025-10-25 18:35:51 +07:00
parent 38e6998ff3
commit f816b8de50
9 changed files with 229 additions and 98 deletions

View File

@@ -371,9 +371,8 @@ public class TradingBotBase : ITradingBot
if (positionForSignal.Status == PositionStatus.Canceled ||
positionForSignal.Status == PositionStatus.Rejected)
{
Logger.LogDebug(
"Skipping update for position {PositionId} - status is {Status} (never filled)",
positionForSignal.Identifier, positionForSignal.Status);
await LogDebug(
$"Skipping update for position {positionForSignal.Identifier} - status is {positionForSignal.Status} (never filled)");
return;
}
@@ -402,8 +401,12 @@ public class TradingBotBase : ITradingBot
if (!Config.IsForBacktest)
{
var brokerPosition = brokerPositions.FirstOrDefault(p =>
p.Ticker == Config.Ticker && p.OriginDirection == positionForSignal.OriginDirection);
// Improved broker position matching with more robust logic
var brokerPosition = brokerPositions
.Where(p => p.Ticker == Config.Ticker)
.OrderByDescending(p => p.Open?.Date ?? DateTime.MinValue)
.FirstOrDefault(p => p.OriginDirection == positionForSignal.OriginDirection);
if (brokerPosition != null)
{
var previousPositionStatus = internalPosition.Status;
@@ -419,8 +422,8 @@ public class TradingBotBase : ITradingBot
internalPosition.Open.SetStatus(TradeStatus.Filled);
positionForSignal.Open.SetStatus(TradeStatus.Filled);
internalPosition.Open.SetPrice(brokerPosition.Open.Price, 5);
positionForSignal.Open.SetPrice(brokerPosition.Open.Price, 5);
internalPosition.Open.Price = brokerPosition.Open.Price;
positionForSignal.Open.Price = brokerPosition.Open.Price;
// Update Open trade ExchangeOrderId if broker position has one
if (brokerPosition.Open?.ExchangeOrderId != null && internalPosition.Open != null)
@@ -462,12 +465,50 @@ public class TradingBotBase : ITradingBot
}
else
{
// No position on the broker, the position have been closed by the exchange
// Position not found in broker's active positions list
// Need to verify if it was actually closed or just not returned by the API
if (internalPosition.Status.Equals(PositionStatus.Filled))
{
internalPosition.Status = PositionStatus.Finished;
// Call HandleClosedPosition to ensure trade dates are properly updated
await HandleClosedPosition(internalPosition);
Logger.LogWarning(
$"⚠️ Position Sync Issue Detected\n" +
$"Internal position {internalPosition.Identifier} shows Filled\n" +
$"But not found in broker positions list (Count: {brokerPositions.Count})\n" +
$"Checking position history before marking as closed...");
// Verify in exchange history before assuming it's closed
bool existsInHistory = await CheckPositionInExchangeHistory(positionForSignal);
if (existsInHistory)
{
// Position was actually filled and closed by the exchange
Logger.LogInformation(
$"✅ Position Confirmed Closed via History\n" +
$"Position {internalPosition.Identifier} found in exchange history\n" +
$"Proceeding with HandleClosedPosition");
internalPosition.Status = PositionStatus.Finished;
await HandleClosedPosition(internalPosition);
return;
}
else
{
// Position not in history either - could be API issue or timing problem
// Don't immediately close, just log warning and retry next cycle
await LogWarning(
$"⚠️ Position Synchronization Warning\n" +
$"Position `{internalPosition.Identifier}` ({internalPosition.OriginDirection} {Config.Ticker})\n" +
$"Not found in broker positions OR exchange history\n" +
$"Status: `{internalPosition.Status}`\n" +
$"This could indicate:\n" +
$"• API returned incomplete data\n" +
$"• Timing issue with broker API\n" +
$"• Position direction mismatch\n" +
$"Will retry verification on next cycle before taking action");
// Don't change the position status yet - wait for next cycle to verify
await LogDebug(
$"Position {internalPosition.Identifier} will be rechecked on next bot cycle for broker synchronization");
}
}
}
}
@@ -852,7 +893,7 @@ public class TradingBotBase : ITradingBot
private async Task<Position> OpenPosition(LightSignal signal)
{
Logger.LogDebug($"Opening position for {signal.Identifier}");
await LogDebug($"🔓 Opening position for signal: `{signal.Identifier}`");
// Check for any existing open position (not finished) for this ticker
var openedPosition =
@@ -963,12 +1004,12 @@ public class TradingBotBase : ITradingBot
if (!Config.IsForBacktest)
{
await ServiceScopeHelpers.WithScopedService<IMessengerService>(_scopeFactory,
async messengerService => { await messengerService.SendPosition(position); });
}
await ServiceScopeHelpers.WithScopedService<IMessengerService>(_scopeFactory,
async messengerService => { await messengerService.SendPosition(position); });
}
Logger.LogDebug($"Position requested");
return position;
await LogDebug($"Position requested successfully for signal: `{signal.Identifier}`");
return position;
}
else
{
@@ -1104,12 +1145,22 @@ public class TradingBotBase : ITradingBot
List<Position> positions = null;
await ServiceScopeHelpers.WithScopedService<IExchangeService>(_scopeFactory,
async exchangeService => { positions = [.. await exchangeService.GetBrokerPositions(Account)]; });
if (!positions.Any(p => p.Ticker == Config.Ticker))
// Check if there's a position for this ticker on the broker
var brokerPositionForTicker = positions.FirstOrDefault(p => p.Ticker == Config.Ticker);
if (brokerPositionForTicker == null)
{
// No position on broker for this ticker, safe to open
return true;
}
// Handle existing position on broker
await LogDebug(
$"🔍 Broker Position Found\n" +
$"Ticker: {Config.Ticker}\n" +
$"Direction: {brokerPositionForTicker.OriginDirection}\n" +
$"Checking internal positions for synchronization...");
var previousPosition = Positions.Values.LastOrDefault();
List<Trade> orders = null;
await ServiceScopeHelpers.WithScopedService<IExchangeService>(_scopeFactory,
@@ -1118,31 +1169,61 @@ public class TradingBotBase : ITradingBot
orders = [.. await exchangeService.GetOpenOrders(Account, Config.Ticker)];
});
var reason = $"Cannot open position. There is already a position open for {Config.Ticker} on the broker.";
var reason =
$"Cannot open position. There is already a position open for {Config.Ticker} on the broker (Direction: {brokerPositionForTicker.OriginDirection}).";
if (previousPosition != null)
{
if (orders.Count >= 2)
// Check if this position matches the broker position
if (previousPosition.OriginDirection == brokerPositionForTicker.OriginDirection)
{
await SetPositionStatus(previousPosition.SignalIdentifier, PositionStatus.Filled);
// Same direction - this is likely the same position
if (orders.Count >= 2)
{
Logger.LogInformation(
$"✅ Broker Position Matched with Internal Position\n" +
$"Position: {previousPosition.Identifier}\n" +
$"Direction: {previousPosition.OriginDirection}\n" +
$"Orders found: {orders.Count}\n" +
$"Setting status to Filled");
await SetPositionStatus(previousPosition.SignalIdentifier, PositionStatus.Filled);
}
else
{
// Position exists on broker but not enough orders - something is wrong
Logger.LogWarning(
$"⚠️ Incomplete Order Set\n" +
$"Position: {previousPosition.Identifier}\n" +
$"Direction: {previousPosition.OriginDirection}\n" +
$"Expected orders: ≥2, Found: {orders.Count}\n" +
$"This position may need manual intervention");
reason += $" Position exists on broker but only has {orders.Count} orders (expected ≥2).";
}
}
else
{
// Broker already has an open position, cancel the internally created (DB) position
await SetPositionStatus(previousPosition.SignalIdentifier, PositionStatus.Canceled);
if (!Config.IsForBacktest)
{
await UpdatePositionDatabase(previousPosition);
}
// Different direction - possible flip scenario or orphaned position
Logger.LogWarning(
$"⚠️ Direction Mismatch Detected\n" +
$"Internal: {previousPosition.OriginDirection}\n" +
$"Broker: {brokerPositionForTicker.OriginDirection}\n" +
$"This could indicate a flipped position or orphaned broker position");
reason +=
" Position open on broker; internal position has been marked as Canceled.";
$" Direction mismatch: Internal ({previousPosition.OriginDirection}) vs Broker ({brokerPositionForTicker.OriginDirection}).";
}
}
else
{
reason +=
" Position open on broker but not enough orders or no previous position internally saved by the bot";
// Broker has a position but we don't have any internal tracking
Logger.LogWarning(
$"⚠️ Orphaned Broker Position Detected\n" +
$"Broker has position for {Config.Ticker} ({brokerPositionForTicker.OriginDirection})\n" +
$"But no internal position found in bot tracking\n" +
$"This may require manual cleanup");
reason += " Position open on broker but no internal position tracked by the bot.";
}
await LogWarning(reason);
@@ -1158,13 +1239,6 @@ public class TradingBotBase : ITradingBot
public async Task CloseTrade(LightSignal signal, Position position, Trade tradeToClose, decimal lastPrice,
bool tradeClosingPosition = false)
{
if (position.TakeProfit2 != null && position.TakeProfit1.Status == TradeStatus.Filled &&
tradeToClose.TradeType == TradeType.StopMarket)
{
// If trade is the 2nd Take profit
tradeToClose.Quantity = position.TakeProfit2.Quantity;
}
await LogInformation(
$"🔧 Closing {position.OriginDirection} Trade\nTicker: `{Config.Ticker}`\nPrice: `${lastPrice}`\n📋 Type: `{tradeToClose.TradeType}`\n📊 Quantity: `{tradeToClose.Quantity:F5}`");
@@ -1175,6 +1249,7 @@ public class TradingBotBase : ITradingBot
await ServiceScopeHelpers.WithScopedService<IExchangeService>(_scopeFactory,
async exchangeService =>
{
// TODO should also pass the direction to get quantity in correct position
quantity = await exchangeService.GetQuantityInPosition(Account, Config.Ticker);
});
}
@@ -1182,7 +1257,7 @@ public class TradingBotBase : ITradingBot
// Get status of position before closing it. The position might be already close by the exchange
if (!Config.IsForBacktest && quantity == 0)
{
Logger.LogDebug($"Trade already close on exchange");
await LogDebug($"Trade already closed on exchange for position: `{position.Identifier}`");
await HandleClosedPosition(position);
}
else
@@ -1247,39 +1322,44 @@ public class TradingBotBase : ITradingBot
{
try
{
Logger.LogDebug(
await LogDebug(
$"🔍 Fetching Position History from GMX\nPosition: `{position.Identifier}`\nTicker: `{Config.Ticker}`");
var positionHistory = await ServiceScopeHelpers.WithScopedService<IExchangeService, List<Position>>(
_scopeFactory,
async exchangeService =>
{
// Get position history from the last 24 hours
var fromDate = DateTime.UtcNow.AddHours(-1);
// Get position history from the last 24 hours for better coverage
var fromDate = DateTime.UtcNow.AddHours(-24);
var toDate = DateTime.UtcNow;
return await exchangeService.GetPositionHistory(Account, Config.Ticker, fromDate, toDate);
});
// Find the matching position in history based on the most recent closed position
// Find the matching position in history based on the most recent closed position with same direction
if (positionHistory != null && positionHistory.Any())
{
// Get the most recent closed position from GMX
var gmxPosition = positionHistory.OrderByDescending(p => p.Open?.Date ?? DateTime.MinValue)
// Get the most recent closed position from GMX that matches the direction
var brokerPosition = positionHistory
.Where(p => p.OriginDirection == position.OriginDirection) // Ensure same direction
.OrderByDescending(p => p.Open?.Date ?? DateTime.MinValue)
.FirstOrDefault();
if (gmxPosition != null && gmxPosition.ProfitAndLoss != null)
if (brokerPosition != null && brokerPosition.ProfitAndLoss != null)
{
Logger.LogDebug(
$"✅ GMX Position History Found\n" +
await LogDebug(
$"✅ Broker Position History Found\n" +
$"Position: `{position.Identifier}`\n" +
$"GMX Realized PnL (after fees): `${gmxPosition.ProfitAndLoss.Realized:F2}`\n" +
$"Realized PnL (after fees): `${brokerPosition.ProfitAndLoss.Realized:F2}`\n" +
$"Bot's UI Fees: `${position.UiFees:F2}`\n" +
$"Bot's Gas Fees: `${position.GasFees:F2}`");
// Use the actual GMX PnL data (this is already net of fees from GMX)
// We use this for reconciliation with the bot's own calculations
var totalBotFees = position.GasFees + position.UiFees;
var gmxNetPnl = gmxPosition.ProfitAndLoss.Realized; // This is already after GMX fees
var closingVolume = brokerPosition.Open.Price * position.Open.Quantity *
position.Open.Leverage;
var totalBotFees = position.GasFees + position.UiFees +
TradingHelpers.CalculateClosingUiFees(closingVolume);
var gmxNetPnl = brokerPosition.ProfitAndLoss.Realized; // This is already after GMX fees
position.ProfitAndLoss = new ProfitAndLoss
{
@@ -1290,19 +1370,19 @@ public class TradingBotBase : ITradingBot
};
// Update the closing trade price if available
if (gmxPosition.Open != null)
if (brokerPosition.Open != null)
{
var gmxClosingPrice = gmxPosition.Open.Price;
// Determine which trade was the closing trade based on profitability
bool isProfitable = position.ProfitAndLoss.Realized > 0;
var brokerClosingPrice = brokerPosition.Open.Price;
var isProfitable = position.OriginDirection == TradeDirection.Long
? position.Open.Price < brokerClosingPrice
: position.Open.Price > brokerClosingPrice;
if (isProfitable)
{
if (position.TakeProfit1 != null)
{
position.TakeProfit1.SetPrice(gmxClosingPrice, 2);
position.TakeProfit1.SetDate(gmxPosition.Open.Date);
position.TakeProfit1.Price = brokerClosingPrice;
position.TakeProfit1.SetDate(brokerPosition.Open.Date);
position.TakeProfit1.SetStatus(TradeStatus.Filled);
}
@@ -1316,8 +1396,8 @@ public class TradingBotBase : ITradingBot
{
if (position.StopLoss != null)
{
position.StopLoss.SetPrice(gmxClosingPrice, 2);
position.StopLoss.SetDate(gmxPosition.Open.Date);
position.StopLoss.Price = brokerClosingPrice;
position.StopLoss.SetDate(brokerPosition.Open.Date);
position.StopLoss.SetStatus(TradeStatus.Filled);
}
@@ -1333,12 +1413,12 @@ public class TradingBotBase : ITradingBot
}
}
Logger.LogDebug(
await LogDebug(
$"📊 Position Reconciliation Complete\n" +
$"Position: `{position.Identifier}`\n" +
$"Closing Price: `${gmxClosingPrice:F2}`\n" +
$"Closing Price: `${brokerClosingPrice:F2}`\n" +
$"Used: `{(isProfitable ? "Take Profit" : "Stop Loss")}`\n" +
$"PnL from GMX: `${position.ProfitAndLoss.Realized:F2}`");
$"PnL from broker: `${position.ProfitAndLoss.Realized:F2}`");
}
// Skip the candle-based PnL calculation since we have actual GMX data
@@ -1457,7 +1537,7 @@ public class TradingBotBase : ITradingBot
position.TakeProfit2.SetStatus(TradeStatus.Cancelled);
}
Logger.LogDebug(
await LogDebug(
$"🛑 Stop Loss Execution Confirmed\n" +
$"Position: `{position.Identifier}`\n" +
$"SL Price: `${closingPrice:F2}` was hit (was `${position.StopLoss.Price:F2}`)\n" +
@@ -1480,7 +1560,7 @@ public class TradingBotBase : ITradingBot
position.StopLoss.SetStatus(TradeStatus.Cancelled);
}
Logger.LogDebug(
await LogDebug(
$"🎯 Take Profit Execution Confirmed\n" +
$"Position: `{position.Identifier}`\n" +
$"TP Price: `${closingPrice:F2}` was hit (was `${position.TakeProfit1.Price:F2}`)\n" +
@@ -1535,7 +1615,7 @@ public class TradingBotBase : ITradingBot
}
}
Logger.LogDebug(
await LogDebug(
$"✋ Manual/Exchange Close Detected\n" +
$"Position: `{position.Identifier}`\n" +
$"SL: `${position.StopLoss.Price:F2}` | TP: `${position.TakeProfit1.Price:F2}`\n" +
@@ -1604,7 +1684,7 @@ public class TradingBotBase : ITradingBot
position.ProfitAndLoss.Net = netPnl;
}
Logger.LogDebug(
await LogDebug(
$"💰 P&L Calculated for Position {position.Identifier}\n" +
$"Entry: `${entryPrice:F2}` | Exit: `${closingPrice:F2}`\n" +
$"Realized P&L: `${pnl:F2}` | Net P&L (after fees): `${position.ProfitAndLoss.Net:F2}`\n" +
@@ -1635,30 +1715,29 @@ public class TradingBotBase : ITradingBot
}
else
{
Logger.LogDebug(
"Skipping PositionClosed notification for position {PositionId} - position was never filled (Open trade status: {OpenStatus})",
position.Identifier, position.Open?.Status);
await LogDebug(
$"Skipping PositionClosed notification for position {position.Identifier} - position was never filled (Open trade status: {position.Open?.Status})");
}
}
// Only update balance and log success if position was actually filled
if (position.Open?.Status == TradeStatus.Filled)
{
Logger.LogDebug(
await LogDebug(
$"✅ Position Closed Successfully\nPosition: `{position.SignalIdentifier}`\nPnL: `${position.ProfitAndLoss?.Net:F2}`");
if (position.ProfitAndLoss != null)
{
Config.BotTradingBalance += position.ProfitAndLoss.Net;
Logger.LogDebug(
await LogDebug(
string.Format("💰 Balance Updated\nNew bot trading balance: `${0:F2}`",
Config.BotTradingBalance));
}
}
else
{
Logger.LogDebug(
await LogDebug(
$"✅ Position Cleanup\nPosition: `{position.SignalIdentifier}` was never filled - no balance or PnL changes");
}
}
@@ -1701,24 +1780,24 @@ public class TradingBotBase : ITradingBot
if (cancelClose)
{
Logger.LogDebug($"Position still open, cancel close orders");
await LogDebug($"Position still open, cancel close orders");
}
else
{
Logger.LogDebug($"Canceling all orders for {Config.Ticker}");
await LogDebug($"Canceling all orders for {Config.Ticker}");
await ServiceScopeHelpers.WithScopedService<IExchangeService>(_scopeFactory,
async exchangeService =>
{
await exchangeService.CancelOrder(Account, Config.Ticker);
var closePendingOrderStatus = await exchangeService.CancelOrder(Account, Config.Ticker);
Logger.LogDebug(
await LogDebug(
$"Closing all {Config.Ticker} orders status : {closePendingOrderStatus}");
});
}
}
else
{
Logger.LogDebug($"No need to cancel orders for {Config.Ticker}");
await LogDebug($"No need to cancel orders for {Config.Ticker}");
}
}
catch (Exception ex)
@@ -1896,6 +1975,27 @@ public class TradingBotBase : ITradingBot
}
}
public async Task LogDebug(string message)
{
if (Config.IsForBacktest)
return;
Logger.LogDebug(message);
try
{
await ServiceScopeHelpers.WithScopedService<IMessengerService>(_scopeFactory,
async messengerService =>
{
await messengerService.SendDebugMessage($"🤖 {Account.User.AgentName} - {Config.Name}\n{message}");
});
}
catch (Exception e)
{
Console.WriteLine(e);
}
}
private async Task SendTradeMessage(string message, bool isBadBehavior = false)
{
if (!Config.IsForBacktest)
@@ -1977,12 +2077,12 @@ public class TradingBotBase : ITradingBot
signalValidationResult.IsBlocked)
{
signal.Status = SignalStatus.Expired;
Logger.LogDebug($"Signal {signal.Identifier} blocked by Synth risk assessment");
await LogDebug($"Signal {signal.Identifier} blocked by Synth risk assessment");
}
else
{
signal.Confidence = signalValidationResult.Confidence;
Logger.LogDebug(
await LogDebug(
$"Signal {signal.Identifier} passed Synth risk assessment with confidence {signalValidationResult.Confidence}");
}
});
@@ -2001,7 +2101,7 @@ public class TradingBotBase : ITradingBot
});
}
Logger.LogDebug(
await LogDebug(
$"Processed signal for {Config.Ticker}: {signal.Direction} with status {signal.Status}");
}
catch (Exception ex)
@@ -2376,8 +2476,7 @@ public class TradingBotBase : ITradingBot
if (LastCandle != null)
{
Logger.LogDebug("Successfully refreshed last candle for {Ticker} at {Date}",
Config.Ticker, LastCandle.Date);
await LogDebug($"Successfully refreshed last candle for {Config.Ticker} at {LastCandle.Date}");
}
else
{
@@ -2472,8 +2571,7 @@ public class TradingBotBase : ITradingBot
await agentGrain.OnPositionOpenedAsync(positionOpenEvent);
await platformGrain.OnPositionOpenAsync(positionOpenEvent);
Logger.LogDebug("Sent position opened event to both grains for position {PositionId}",
position.Identifier);
await LogDebug($"Sent position opened event to both grains for position {position.Identifier}");
break;
case NotificationEventType.PositionClosed:
@@ -2488,8 +2586,7 @@ public class TradingBotBase : ITradingBot
await agentGrain.OnPositionClosedAsync(positionClosedEvent);
await platformGrain.OnPositionClosedAsync(positionClosedEvent);
Logger.LogDebug("Sent position closed event to both grains for position {PositionId}",
position.Identifier);
await LogDebug($"Sent position closed event to both grains for position {position.Identifier}");
break;
case NotificationEventType.PositionUpdated:
@@ -2501,8 +2598,7 @@ public class TradingBotBase : ITradingBot
await agentGrain.OnPositionUpdatedAsync(positionUpdatedEvent);
// No need to notify platform grain, it will be notified when position is closed or opened only
Logger.LogDebug("Sent position updated event to both grains for position {PositionId}",
position.Identifier);
await LogDebug($"Sent position updated event to both grains for position {position.Identifier}");
break;
}
});
@@ -2530,39 +2626,51 @@ public class TradingBotBase : ITradingBot
try
{
Logger.LogDebug(
await LogDebug(
$"🔍 Checking Position History for Position: `{position.Identifier}`\nTicker: `{Config.Ticker}`");
List<Position> positionHistory = null;
await ServiceScopeHelpers.WithScopedService<IExchangeService>(_scopeFactory,
async exchangeService =>
{
// Get position history from the last 24 hours
var fromDate = DateTime.UtcNow.AddMinutes(-10);
// Get position history from the last 24 hours for comprehensive check
var fromDate = DateTime.UtcNow.AddHours(-24);
var toDate = DateTime.UtcNow;
positionHistory =
await exchangeService.GetPositionHistory(Account, Config.Ticker, fromDate, toDate);
});
// Check if there's a recent position with PnL data
// Check if there's a recent position with PnL data and matching direction
if (positionHistory != null && positionHistory.Any())
{
var recentPosition = positionHistory
.Where(p => p.OriginDirection == position.OriginDirection) // Ensure same direction
.OrderByDescending(p => p.Open?.Date ?? DateTime.MinValue)
.FirstOrDefault();
if (recentPosition != null && recentPosition.ProfitAndLoss != null)
{
Logger.LogDebug(
await LogDebug(
$"✅ Position Found in Exchange History\n" +
$"Position: `{position.Identifier}`\n" +
$"Direction: `{position.OriginDirection}` (Matched: ✅)\n" +
$"Exchange PnL: `${recentPosition.ProfitAndLoss.Realized:F2}`\n" +
$"Position was actually filled and closed");
return true;
}
else
{
// Found positions in history but none match the direction
var allHistoryDirections = positionHistory.Select(p => p.OriginDirection).Distinct().ToList();
await LogDebug(
$"⚠️ Direction Mismatch in History\n" +
$"Looking for: `{position.OriginDirection}`\n" +
$"Found in history: `{string.Join(", ", allHistoryDirections)}`\n" +
$"No matching position found");
}
}
Logger.LogDebug(
await LogDebug(
$"❌ No Position Found in Exchange History\nPosition: `{position.Identifier}`\nPosition was never filled");
return false;
}