From 307f251576a3f428933d61440bb2b306d929b535 Mon Sep 17 00:00:00 2001 From: rob Date: Fri, 6 Mar 2026 23:34:55 -0400 Subject: [PATCH] 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 --- src/backtest_strategy_instance.py | 45 ++++++++- src/backtesting.py | 152 +++++++++++++++++++++++------- src/mapped_strategy.py | 32 ++++++- src/static/backtesting.js | 94 ++++++++++++++++++ src/static/charts.js | 111 ++++++++++++++++++++++ 5 files changed, 391 insertions(+), 43 deletions(-) diff --git a/src/backtest_strategy_instance.py b/src/backtest_strategy_instance.py index fc31557..764e880 100644 --- a/src/backtest_strategy_instance.py +++ b/src/backtest_strategy_instance.py @@ -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): """ diff --git a/src/backtesting.py b/src/backtesting.py index bd0c016..4a03662 100644 --- a/src/backtesting.py +++ b/src/backtesting.py @@ -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 + # 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) + ) + + 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(): - # 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 - ) + logger.info(f"[BACKTEST] Computing indicator '{indicator_name}' on backtest data feed") - if not indicator_data: - logger.warning(f"No data returned for indicator '{indicator_name}'. Skipping.") - continue + 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)] + ) - data = indicator_data.get(indicator_name) - - # 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.") - continue - - # 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] - if missing_columns: - logger.warning(f"Indicator '{indicator_name}' missing columns: {missing_columns}. Skipping.") + if indicators.empty: + logger.warning(f"[BACKTEST] Indicator '{indicator_name}' not found for user '{user_name}' (id={user_id}). Skipping.") continue - df = 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.") + indicator = indicators.iloc[0] + kind = indicator['kind'] + properties = json_module.loads(indicator['properties']) if isinstance(indicator['properties'], str) else indicator['properties'] + + 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 result_df.columns] + if missing_columns: + 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 + 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) diff --git a/src/mapped_strategy.py b/src/mapped_strategy.py index 432e88d..382d9b4 100644 --- a/src/mapped_strategy.py +++ b/src/mapped_strategy.py @@ -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: diff --git a/src/static/backtesting.js b/src/static/backtesting.js index 81a5028..ffef3da 100644 --- a/src/static/backtesting.js +++ b/src/static/backtesting.js @@ -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 { Trade ID + Open Time + Close Time Size Open Price Close Price @@ -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 += ` ${trade.ref} + ${openTime} + ${closeTime} ${size} ${openPrice} ${closePrice} @@ -277,6 +286,9 @@ class Backtesting { `; }); + + // Automatically show trade markers on chart + this.showTradeMarkersOnChart(results.trades, results.trading_source); html += ` @@ -287,6 +299,36 @@ class Backtesting { html += `

No trades were executed.

`; } + // Strategy Alerts Section + if (results.alerts && results.alerts.length > 0) { + html += ` +

Strategy Alerts

+
+ + + + + + + + + `; + results.alerts.forEach(alert => { + const timestamp = alert.timestamp ? this.formatTradeDateTime(alert.timestamp) : 'N/A'; + html += ` + + + + + `; + }); + html += ` + +
TimestampMessage
${timestamp}${alert.message || ''}
+
+ `; + } + 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(); + } + } + } diff --git a/src/static/charts.js b/src/static/charts.js index 552ffa9..e4f1348 100644 --- a/src/static/charts.js +++ b/src/static/charts.js @@ -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; + } + } + }