Add backtest debugging features: timestamps, chart markers, and alerts

- Add Open/Close Time columns to Trades Executed table
- Display trade markers (buy/sell arrows) automatically on chart
- Clear markers when closing results dialog or running new test
- Collect notify_user alerts with timestamps during backtesting
- Display Strategy Alerts section in backtest results
- Fix timestamp conversion: use unit='s' for EDM timestamps (not 'ms')
- Fix trade datetime extraction using data feed's datetime method

Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
This commit is contained in:
rob 2026-03-06 23:34:55 -04:00
parent 3e6463e4b3
commit 307f251576
5 changed files with 391 additions and 43 deletions

View File

@ -49,6 +49,9 @@ class BacktestStrategyInstance(StrategyInstance):
# Initialize last_valid_values for indicators
self.last_valid_values={}
# Initialize collected alerts for backtest results
self.collected_alerts = []
def set_backtrader_strategy(self, backtrader_strategy: bt.Strategy):
"""
Sets the backtrader_strategy and initializes broker-dependent attributes.
@ -147,14 +150,15 @@ class BacktestStrategyInstance(StrategyInstance):
If no last valid value exists, searches forward for the next valid value.
If no valid value is found, returns a default value (e.g., 1).
"""
logger.debug(f"Backtester is retrieving indicator '{indicator_name}' from precomputed data.")
logger.info(f"[BACKTEST] process_indicator called: indicator='{indicator_name}', output='{output_field}'")
if self.backtrader_strategy is None:
logger.error("Backtrader strategy is not set in StrategyInstance.")
return None
df = self.backtrader_strategy.precomputed_indicators.get(indicator_name)
if df is None:
logger.error(f"Indicator '{indicator_name}' not found.")
logger.error(f"[BACKTEST DEBUG] Indicator '{indicator_name}' not found in precomputed_indicators!")
logger.error(f"[BACKTEST DEBUG] Available indicators: {list(self.backtrader_strategy.precomputed_indicators.keys())}")
return None
idx = self.backtrader_strategy.indicator_pointers.get(indicator_name, 0)
@ -165,6 +169,10 @@ class BacktestStrategyInstance(StrategyInstance):
# Retrieve the value at the current index
value = df.iloc[idx].get(output_field)
# Log indicator values for debugging (first 10 and every 50th)
if idx < 10 or idx % 50 == 0:
logger.info(f"[BACKTEST] process_indicator('{indicator_name}', '{output_field}') at idx={idx}: raw_value={value}")
if pd.isna(value):
# Check if we have a cached last valid value
last_valid_value = self.last_valid_values.get(indicator_name, {}).get(output_field)
@ -195,6 +203,10 @@ class BacktestStrategyInstance(StrategyInstance):
if indicator_name not in self.last_valid_values:
self.last_valid_values[indicator_name] = {}
self.last_valid_values[indicator_name][output_field] = value
# Log the returned value for debugging
idx = self.backtrader_strategy.indicator_pointers.get(indicator_name, 0)
if idx < 10 or idx % 50 == 0:
logger.info(f"[BACKTEST] process_indicator returning: {indicator_name}.{output_field} = {value}")
return value
# 3. Override get_current_price
@ -303,10 +315,35 @@ class BacktestStrategyInstance(StrategyInstance):
# 9. Override notify_user
def notify_user(self, message: str):
"""
Suppresses user notifications and instead logs them.
Collects notifications with timestamps for display in backtest results.
:param message: Notification message.
"""
logger.debug(f"Backtest notification: {message}")
timestamp = self.get_current_candle_datetime()
alert = {
'timestamp': timestamp.isoformat() if timestamp else None,
'message': message
}
self.collected_alerts.append(alert)
logger.debug(f"Backtest notification: {message} (at {timestamp})")
def get_current_candle_datetime(self) -> dt.datetime:
"""
Gets the datetime of the current candle from backtrader's data feed.
"""
if self.backtrader_strategy is None:
return dt.datetime.now()
try:
# Use the data feed's datetime method to get proper datetime
return self.backtrader_strategy.data.datetime.datetime(0)
except Exception as e:
logger.warning(f"Could not get candle datetime: {e}")
return dt.datetime.now()
def get_collected_alerts(self) -> list:
"""
Returns the list of collected alerts for inclusion in backtest results.
"""
return self.collected_alerts
def save_context(self):
"""

View File

@ -323,11 +323,23 @@ class Backtester:
def precompute_indicators(self, indicators_definitions: list, user_name: str, data_feed: pd.DataFrame) -> dict:
"""
Precompute indicator values and return a dictionary of DataFrames.
Precompute indicator values directly on the backtest data feed.
IMPORTANT: This computes indicators on the actual backtest candle data,
ensuring the indicator values align with the price data used in the backtest.
Previously, this fetched fresh/latest candles which caused misalignment.
"""
import json as json_module # Local import to avoid conflicts
precomputed_indicators = {}
total_candles = len(data_feed)
logger.info(f"[BACKTEST] precompute_indicators called with {len(indicators_definitions)} indicator definitions")
logger.info(f"[BACKTEST] user_name: {user_name}, total_candles: {total_candles}")
logger.info(f"[BACKTEST] data_feed columns: {list(data_feed.columns)}")
logger.info(f"[BACKTEST] data_feed first row: {data_feed.iloc[0].to_dict() if len(data_feed) > 0 else 'empty'}")
logger.info(f"[BACKTEST] data_feed last row: {data_feed.iloc[-1].to_dict() if len(data_feed) > 0 else 'empty'}")
# Aggregate requested outputs for each indicator
indicator_outputs = {}
for indicator_def in indicators_definitions:
@ -350,44 +362,83 @@ class Backtester:
# If output is None, we need all outputs
indicator_outputs[indicator_name] = None # None indicates all outputs
# Now, precompute each unique indicator with the required outputs
for indicator_name, outputs in indicator_outputs.items():
# Compute the indicator values
indicator_data = self.indicators_manager.get_latest_indicator_data(
user_name=user_name,
indicator_name=indicator_name,
num_results=total_candles
# Get user ID for indicator lookup
user_id = self.data_cache.get_datacache_item(
item_name='id',
cache_name='users',
filter_vals=('user_name', user_name)
)
if not indicator_data:
logger.warning(f"No data returned for indicator '{indicator_name}'. Skipping.")
logger.info(f"[BACKTEST] indicator_outputs to precompute: {indicator_outputs}")
# Prepare candle data for indicator calculation
# Convert data_feed to the format expected by indicators
candle_data = data_feed.copy()
# Ensure required columns exist
if 'time' not in candle_data.columns and candle_data.index.name == 'datetime':
candle_data['time'] = candle_data.index.astype(np.int64) // 10**6 # Convert to milliseconds
for indicator_name, outputs in indicator_outputs.items():
logger.info(f"[BACKTEST] Computing indicator '{indicator_name}' on backtest data feed")
try:
# Fetch indicator definition from cache
indicators = self.data_cache.get_rows_from_datacache(
cache_name='indicators',
filter_vals=[('creator', str(user_id)), ('name', indicator_name)]
)
if indicators.empty:
logger.warning(f"[BACKTEST] Indicator '{indicator_name}' not found for user '{user_name}' (id={user_id}). Skipping.")
continue
data = indicator_data.get(indicator_name)
indicator = indicators.iloc[0]
kind = indicator['kind']
properties = json_module.loads(indicator['properties']) if isinstance(indicator['properties'], str) else indicator['properties']
# Convert the data to a DataFrame
if isinstance(data, list):
df = pd.DataFrame(data)
elif isinstance(data, dict):
df = pd.DataFrame([data])
else:
logger.warning(f"Unexpected data format for indicator '{indicator_name}'. Skipping.")
logger.info(f"[BACKTEST] Indicator '{indicator_name}' is of kind '{kind}' with properties: {properties}")
# Get the indicator class from the registry
indicator_class = self.indicators_manager.indicator_registry.get(kind)
if not indicator_class:
logger.warning(f"[BACKTEST] Unknown indicator kind '{kind}' for '{indicator_name}'. Skipping.")
continue
# Instantiate and calculate
indicator_obj = indicator_class(name=indicator_name, indicator_type=kind, properties=properties)
result_df = indicator_obj.calculate(candles=candle_data, user_name=user_name, num_results=total_candles)
if result_df is None or (isinstance(result_df, pd.DataFrame) and result_df.empty):
logger.warning(f"[BACKTEST] No data computed for indicator '{indicator_name}'. Skipping.")
continue
logger.info(f"[BACKTEST] Computed indicator '{indicator_name}': {len(result_df)} rows, columns: {list(result_df.columns)}")
# Log first few values for debugging
if len(result_df) > 0:
logger.info(f"[BACKTEST] First 3 rows of '{indicator_name}': {result_df.head(3).to_dict('records')}")
logger.info(f"[BACKTEST] Last 3 rows of '{indicator_name}': {result_df.tail(3).to_dict('records')}")
# If outputs is None, keep all outputs
if outputs is not None:
# Include 'time' and requested outputs
columns_to_keep = ['time'] + list(outputs)
missing_columns = [col for col in columns_to_keep if col not in df.columns]
missing_columns = [col for col in columns_to_keep if col not in result_df.columns]
if missing_columns:
logger.warning(f"Indicator '{indicator_name}' missing columns: {missing_columns}. Skipping.")
continue
df = df[columns_to_keep]
logger.warning(f"[BACKTEST] Indicator '{indicator_name}' missing columns: {missing_columns}. Available: {list(result_df.columns)}")
# Try to continue with available columns
columns_to_keep = [c for c in columns_to_keep if c in result_df.columns]
result_df = result_df[columns_to_keep]
# Reset index and store the DataFrame
df.reset_index(drop=True, inplace=True)
precomputed_indicators[indicator_name] = df
logger.debug(f"Precomputed indicator '{indicator_name}' with {len(df)} data points.")
result_df.reset_index(drop=True, inplace=True)
precomputed_indicators[indicator_name] = result_df
logger.info(f"[BACKTEST] Precomputed indicator '{indicator_name}' with {len(result_df)} data points.")
except Exception as e:
logger.error(f"[BACKTEST] Error computing indicator '{indicator_name}': {e}", exc_info=True)
continue
return precomputed_indicators
@ -428,6 +479,18 @@ class Backtester:
indicators_definitions = strategy_components.get('indicators', [])
precomputed_indicators = self.precompute_indicators(indicators_definitions, user_name, data_feed)
# Align data feed with indicator data by trimming to match the shortest indicator
# Indicators skip their warmup period, so they have fewer rows than the raw candle data
if precomputed_indicators:
min_indicator_len = min(len(df) for df in precomputed_indicators.values())
original_len = len(data_feed)
if min_indicator_len < original_len:
# Trim the data feed from the beginning to align with indicators
warmup_period = original_len - min_indicator_len
data_feed = data_feed.iloc[warmup_period:].reset_index(drop=True)
logger.info(f"[BACKTEST] Trimmed data feed from {original_len} to {len(data_feed)} rows to align with indicators (warmup period: {warmup_period})")
logger.info("Backtest data prepared successfully.")
return data_feed, precomputed_indicators
@ -446,7 +509,16 @@ class Backtester:
try:
# **Convert 'time' to 'datetime' if necessary**
if 'time' in data_feed.columns:
data_feed['datetime'] = pd.to_datetime(data_feed['time'], unit='ms')
# Time values from EDM are Unix timestamps in SECONDS, not milliseconds
data_feed['datetime'] = pd.to_datetime(data_feed['time'], unit='s')
# DEBUG: Log first and last timestamps to verify conversion
if len(data_feed) > 0:
first_time = data_feed['time'].iloc[0]
last_time = data_feed['time'].iloc[-1]
first_dt = data_feed['datetime'].iloc[0]
last_dt = data_feed['datetime'].iloc[-1]
logger.info(f"[DEBUG DATETIME FIX] First raw time: {first_time}, converted: {first_dt}")
logger.info(f"[DEBUG DATETIME FIX] Last raw time: {last_time}, converted: {last_dt}")
data_feed.set_index('datetime', inplace=True)
logger.info("Converted 'time' to 'datetime' and set as index in data_feed.")
@ -509,6 +581,12 @@ class Backtester:
'progress': 100}}
, room=socket_conn_id)
# Get collected alerts from strategy instance
collected_alerts = strategy_instance.get_collected_alerts()
# Get trading source info for chart validation
trading_source = msg_data.get('trading_source', {})
# Prepare the results to pass into the callback
backtest_results = {
"success": True, # Indicate success
@ -517,6 +595,8 @@ class Backtester:
"run_duration": run_duration,
"equity_curve": equity_curve,
"trades": trades,
"alerts": collected_alerts,
"trading_source": trading_source,
}
logger.info("Backtest executed successfully.")
@ -597,6 +677,8 @@ class Backtester:
}
logger.info(f"Using default_source for backtest data: {source}")
strategy_components['data_sources'] = [source]
# Store trading source in msg_data for inclusion in backtest results
msg_data['trading_source'] = source
try:
data_feed, precomputed_indicators = self.prepare_backtest_data(msg_data, strategy_components)

View File

@ -87,9 +87,13 @@ class MappedStrategy(bt.Strategy):
f"notify_trade called for trade {trade.ref}, PnL: {trade.pnl}, Status: {trade.status_names[trade.status]}")
if trade.isopen:
# Trade just opened
# Trade just opened - use current bar's datetime from data feed
current_dt = self.data.datetime.datetime(0)
open_datetime = current_dt.isoformat() if current_dt else None
# Debug logging
raw_dt = self.data.datetime[0]
logger.info(f"[DEBUG] Trade open - raw datetime[0]={raw_dt}, converted={current_dt}, iso={open_datetime}")
self.log(f"TRADE OPENED, Size: {trade.size}, Price: {trade.price}")
open_datetime = bt.num2date(trade.dtopen).isoformat() if trade.dtopen else None
trade_info = {
'ref': trade.ref,
'size': trade.size,
@ -99,9 +103,10 @@ class MappedStrategy(bt.Strategy):
# Store the trade_info with trade.ref as key
self.open_trades[trade.ref] = trade_info
elif trade.isclosed:
# Trade just closed
# Trade just closed - use current bar's datetime from data feed
current_dt = self.data.datetime.datetime(0)
close_datetime = current_dt.isoformat() if current_dt else None
self.log(f"TRADE CLOSED, GROSS P/L: {trade.pnl}, NET P/L: {trade.pnlcomm}")
close_datetime = bt.num2date(trade.dtclose).isoformat() if trade.dtclose else None
# Retrieve open trade details
trade_info = self.open_trades.pop(trade.ref, {})
# Get the close price from data feed
@ -129,9 +134,28 @@ class MappedStrategy(bt.Strategy):
self.current_step += 1
# Debug: Log current price and indicator values every N steps
if self.current_step <= 10 or self.current_step % 50 == 0:
current_price = self.data.close[0]
logger.info(f"[BACKTEST STEP {self.current_step}] Price: {current_price:.2f}")
# Log all indicator values at this step
for ind_name, df in self.precomputed_indicators.items():
idx = self.indicator_pointers.get(ind_name, 0)
if idx < len(df):
row = df.iloc[idx]
# Log all columns except 'time'
values = {col: row[col] for col in df.columns if col != 'time'}
logger.info(f"[BACKTEST STEP {self.current_step}] Indicator '{ind_name}' at idx {idx}: {values}")
# Execute the strategy logic
self.execute_strategy()
# Advance indicator pointers for the next candle
for name in self.indicator_names:
if name in self.indicator_pointers:
self.indicator_pointers[name] += 1
# Check if we're at the second-to-last bar
if self.current_step == (self.p.data_length - 1):
if self.position:

View File

@ -207,6 +207,9 @@ class Backtesting {
this.setText(this.progressBar, '0%');
this.resultsDisplay.innerHTML = ''; // Clear previous results
this.displayMessage('Backtest started...', 'blue');
// Clear previous trade markers from chart
this.clearTradeMarkers();
}
displayTestResults(results) {
@ -253,6 +256,8 @@ class Backtesting {
<thead>
<tr>
<th>Trade ID</th>
<th>Open Time</th>
<th>Close Time</th>
<th>Size</th>
<th>Open Price</th>
<th>Close Price</th>
@ -266,10 +271,14 @@ class Backtesting {
const openPrice = trade.open_price != null ? trade.open_price.toFixed(2) : 'N/A';
const closePrice = trade.close_price != null ? trade.close_price.toFixed(2) : 'N/A';
const pnl = trade.pnl != null ? trade.pnl.toFixed(2) : 'N/A';
const openTime = trade.open_datetime ? this.formatTradeDateTime(trade.open_datetime) : 'N/A';
const closeTime = trade.close_datetime ? this.formatTradeDateTime(trade.close_datetime) : 'N/A';
html += `
<tr>
<td>${trade.ref}</td>
<td>${openTime}</td>
<td>${closeTime}</td>
<td>${size}</td>
<td>${openPrice}</td>
<td>${closePrice}</td>
@ -277,6 +286,9 @@ class Backtesting {
</tr>
`;
});
// Automatically show trade markers on chart
this.showTradeMarkersOnChart(results.trades, results.trading_source);
html += `
</tbody>
</table>
@ -287,6 +299,36 @@ class Backtesting {
html += `<p>No trades were executed.</p>`;
}
// Strategy Alerts Section
if (results.alerts && results.alerts.length > 0) {
html += `
<h4>Strategy Alerts</h4>
<div style="max-height: 200px; overflow-y: auto;">
<table border="1" cellpadding="5" cellspacing="0">
<thead>
<tr>
<th>Timestamp</th>
<th>Message</th>
</tr>
</thead>
<tbody>
`;
results.alerts.forEach(alert => {
const timestamp = alert.timestamp ? this.formatTradeDateTime(alert.timestamp) : 'N/A';
html += `
<tr>
<td>${timestamp}</td>
<td>${alert.message || ''}</td>
</tr>
`;
});
html += `
</tbody>
</table>
</div>
`;
}
this.resultsDisplay.innerHTML = html;
this.drawEquityCurveChart(results.equity_curve);
}
@ -544,6 +586,9 @@ class Backtesting {
this.hideElement(this.resultsContainer);
this.hideElement(this.progressContainer);
this.clearMessage();
// Clear trade markers from chart
this.clearTradeMarkers();
}
clearForm() {
@ -641,5 +686,54 @@ class Backtesting {
return `${year}-${month}-${day}T${hours}:${minutes}`;
}
// Format trade datetime for display in trades table
formatTradeDateTime(dateTimeStr) {
if (!dateTimeStr) return 'N/A';
try {
const date = new Date(dateTimeStr);
const pad = (num) => num.toString().padStart(2, '0');
const month = pad(date.getMonth() + 1);
const day = pad(date.getDate());
const hours = pad(date.getHours());
const minutes = pad(date.getMinutes());
return `${month}/${day} ${hours}:${minutes}`;
} catch (e) {
return dateTimeStr;
}
}
// Show all trade markers on chart for the backtest results
showTradeMarkersOnChart(trades, tradingSource) {
// Check if charts are available
if (!this.ui.charts) {
console.log('Charts not available, skipping trade markers');
return;
}
// Validate that the current chart matches the backtest's trading source
const normalizeSymbol = (s) => (s || '').toUpperCase().replace(/[\/\-]/g, '');
const currentNormalized = normalizeSymbol(this.ui.charts.trading_pair);
const backtestNormalized = normalizeSymbol(tradingSource?.symbol);
if (tradingSource?.symbol && currentNormalized !== backtestNormalized) {
console.log(`Chart mismatch: viewing "${this.ui.charts.trading_pair}" but backtest ran on "${tradingSource.symbol}". Skipping markers.`);
return;
}
// Call the chart function to show all trade markers
if (typeof this.ui.charts.setTradeMarkers === 'function') {
this.ui.charts.setTradeMarkers(trades);
} else {
console.warn('setTradeMarkers function not available on charts');
}
}
// Clear trade markers from chart
clearTradeMarkers() {
if (this.ui.charts && typeof this.ui.charts.clearTradeMarkers === 'function') {
this.ui.charts.clearTradeMarkers();
}
}
}

View File

@ -219,5 +219,116 @@ class Charts {
this.bound_charts[3].timeScale().subscribeVisibleTimeRangeChange(syncFromChart(3));
}
// Set trade markers on chart for all trades in backtest results
setTradeMarkers(trades) {
if (!this.candleSeries) {
console.warn('Candlestick series not available');
return;
}
if (!trades || trades.length === 0) {
console.log('No trades to display as markers');
return;
}
const candleData = this.price_history || [];
if (candleData.length === 0) {
console.warn('No candle data available for markers');
return;
}
// Get the time range of loaded candle data
const minCandleTime = candleData[0].time;
const maxCandleTime = candleData[candleData.length - 1].time;
console.log(`Chart data range: ${minCandleTime} to ${maxCandleTime}`);
// Build markers array from all trades
const markers = [];
trades.forEach(trade => {
const openTime = this.dateStringToUnixTimestamp(trade.open_datetime);
const closeTime = trade.close_datetime ? this.dateStringToUnixTimestamp(trade.close_datetime) : null;
// Add entry marker if within chart data range
if (openTime && openTime >= minCandleTime && openTime <= maxCandleTime) {
const matchedOpenTime = this.findNearestCandleTime(openTime, candleData);
markers.push({
time: matchedOpenTime,
position: 'belowBar',
color: '#26a69a',
shape: 'arrowUp',
text: 'BUY @ ' + (trade.open_price ? trade.open_price.toFixed(2) : '')
});
}
// Add exit marker if within chart data range
if (closeTime && closeTime >= minCandleTime && closeTime <= maxCandleTime) {
const matchedCloseTime = this.findNearestCandleTime(closeTime, candleData);
markers.push({
time: matchedCloseTime,
position: 'aboveBar',
color: '#ef5350',
shape: 'arrowDown',
text: 'SELL @ ' + (trade.close_price ? trade.close_price.toFixed(2) : '')
});
}
});
if (markers.length === 0) {
console.log('No trades fall within the loaded chart data timespan');
return;
}
// Sort markers by time (required by lightweight-charts)
markers.sort((a, b) => a.time - b.time);
console.log(`Setting ${markers.length} trade markers on chart`);
// Set markers on the candlestick series
this.candleSeries.setMarkers(markers);
}
// Clear all trade markers from chart
clearTradeMarkers() {
if (this.candleSeries) {
this.candleSeries.setMarkers([]);
console.log('Trade markers cleared');
}
}
// Find the nearest candle time in the data
findNearestCandleTime(targetTime, candleData) {
if (!candleData || candleData.length === 0) {
return targetTime;
}
let nearestTime = candleData[0].time;
let minDiff = Math.abs(targetTime - nearestTime);
for (const candle of candleData) {
const diff = Math.abs(targetTime - candle.time);
if (diff < minDiff) {
minDiff = diff;
nearestTime = candle.time;
}
// Early exit if exact match
if (diff === 0) break;
}
return nearestTime;
}
// Convert datetime string to Unix timestamp in seconds
dateStringToUnixTimestamp(dateStr) {
if (!dateStr) return null;
try {
const date = new Date(dateStr);
return Math.floor(date.getTime() / 1000);
} catch (e) {
console.warn('Failed to parse date:', dateStr, e);
return null;
}
}
}