diff --git a/Algorithm/QCAlgorithm.cs b/Algorithm/QCAlgorithm.cs index 28f1c352f359..3fe98a45f547 100644 --- a/Algorithm/QCAlgorithm.cs +++ b/Algorithm/QCAlgorithm.cs @@ -3817,7 +3817,7 @@ private DateTime GetTimeInExchangeTimeZone(Symbol symbol) private string FormatLog(string message) { - return $"{Time.ToStringInvariant(DateFormat.UI)} {message}"; + return message.PrefixWithAlgorithmTime(Time); } } } diff --git a/Common/Extensions.cs b/Common/Extensions.cs index 92b6c130179f..1a4be7977fff 100644 --- a/Common/Extensions.cs +++ b/Common/Extensions.cs @@ -79,6 +79,18 @@ public static class Extensions private static readonly Dictionary PythonActivators = new Dictionary(); + /// + /// Prefixes the given message with the provided algorithm time, producing the standard + /// timestamped format shared by algorithm logs and messages + /// + /// The message to prefix + /// The algorithm time to prefix the message with + /// The message prefixed with the algorithm time + public static string PrefixWithAlgorithmTime(this string message, DateTime algorithmTime) + { + return $"{algorithmTime.ToStringInvariant(DateFormat.UI)} {message}"; + } + /// /// Maintains old behavior of NodaTime's (< 2.0) daylight savings mapping. /// We keep the old behavior to ensure the FillForwardEnumerator does not get stuck on an infinite loop. diff --git a/Engine/Results/BacktestingResultHandler.cs b/Engine/Results/BacktestingResultHandler.cs index 70051f043138..8b37736c7b90 100644 --- a/Engine/Results/BacktestingResultHandler.cs +++ b/Engine/Results/BacktestingResultHandler.cs @@ -469,6 +469,7 @@ public override void SetAlgorithm(IAlgorithm algorithm, decimal startingPortfoli /// Message we'd like shown in console. public virtual void DebugMessage(string message) { + message = FormatMessage(message); Messages.Enqueue(new DebugPacket(_projectId, AlgorithmId, CompileId, message)); AddToLogStore(message); } @@ -479,6 +480,7 @@ public virtual void DebugMessage(string message) /// Message we'd like shown in console. public virtual void SystemDebugMessage(string message) { + message = FormatMessage(message); Messages.Enqueue(new SystemDebugPacket(_projectId, AlgorithmId, CompileId, message)); AddToLogStore(message); } @@ -489,6 +491,7 @@ public virtual void SystemDebugMessage(string message) /// Message we'd in the log. public virtual void LogMessage(string message) { + message = FormatMessage(message); Messages.Enqueue(new LogPacket(AlgorithmId, message)); AddToLogStore(message); } @@ -502,8 +505,8 @@ public virtual void ErrorMessage(string message, string stacktrace = "") { if (message == _errorMessage) return; if (Messages.Count > 500) return; - Messages.Enqueue(new HandledErrorPacket(AlgorithmId, message, stacktrace)); _errorMessage = message; + Messages.Enqueue(new HandledErrorPacket(AlgorithmId, FormatMessage(message), stacktrace)); } /// @@ -514,8 +517,9 @@ public virtual void ErrorMessage(string message, string stacktrace = "") public virtual void RuntimeError(string message, string stacktrace = "") { PurgeQueue(); - Messages.Enqueue(new RuntimeErrorPacket(_job.UserId, AlgorithmId, message, stacktrace)); _errorMessage = message; + message = FormatMessage(message); + Messages.Enqueue(new RuntimeErrorPacket(_job.UserId, AlgorithmId, message, stacktrace)); SetAlgorithmState(message, stacktrace); } diff --git a/Engine/Results/BaseResultsHandler.cs b/Engine/Results/BaseResultsHandler.cs index 407f55bf1826..97026fa2e113 100644 --- a/Engine/Results/BaseResultsHandler.cs +++ b/Engine/Results/BaseResultsHandler.cs @@ -1122,6 +1122,18 @@ protected StatisticsResults GenerateStatisticsResults(CapacityEstimate estimated return GenerateStatisticsResults(charts, profitLoss, estimatedStrategyCapacity); } + /// + /// Prefixes the given message with the algorithm time, matching the format used by + /// the algorithm's own log messages (see ). Used to normalize + /// the timestamp across all algorithm logs and messages. + /// + /// The message to format + /// The message prefixed with the algorithm time, or the original message if the algorithm is not yet available + protected string FormatMessage(string message) + { + return Algorithm != null ? message.PrefixWithAlgorithmTime(Algorithm.Time) : message; + } + /// /// Save an algorithm message to the log store. Uses a different timestamped method of adding messaging to interweve debug and logging messages. /// @@ -1171,7 +1183,7 @@ private void ProcessAlgorithmLogsImpl(ConcurrentQueue concurrentQueue, P { _packetDroppedWarning = true; // this shouldn't happen in most cases, queue limit is high and consumed often but just in case let's not silently drop packets without a warning - Messages.Enqueue(new HandledErrorPacket(AlgorithmId, "Your algorithm messaging has been rate limited to prevent browser flooding.")); + Messages.Enqueue(new HandledErrorPacket(AlgorithmId, FormatMessage("Your algorithm messaging has been rate limited to prevent browser flooding."))); } //if too many in the queue already skip the logging and drop the messages continue; diff --git a/Engine/Results/LiveTradingResultHandler.cs b/Engine/Results/LiveTradingResultHandler.cs index 954c95cd3411..36374aa5f5dd 100644 --- a/Engine/Results/LiveTradingResultHandler.cs +++ b/Engine/Results/LiveTradingResultHandler.cs @@ -254,8 +254,8 @@ private void Update() var deltaStatistics = new Dictionary(); var orders = new Dictionary(TransactionHandler.Orders); - var complete = new LiveResultPacket(_job, new LiveResult(new LiveResultParameters(chartComplete, orders, - Algorithm.Transactions.TransactionRecord, holdings, Algorithm.Portfolio.CashBook, deltaStatistics, + var complete = new LiveResultPacket(_job, new LiveResult(new LiveResultParameters(chartComplete, orders, + Algorithm.Transactions.TransactionRecord, holdings, Algorithm.Portfolio.CashBook, deltaStatistics, runtimeStatistics, orderEvents, statistics.TotalPerformance, serverStatistics, state: GetAlgorithmState()))); StoreResult(complete); _nextChartsUpdate = DateTime.UtcNow.Add(ChartUpdateInterval); @@ -544,6 +544,7 @@ private IEnumerable SplitPackets(Dictionary del public void DebugMessage(string message) { if (Messages.Count > 500) return; //if too many in the queue already skip the logging. + message = FormatMessage(message); Messages.Enqueue(new DebugPacket(_job.ProjectId, AlgorithmId, CompileId, message)); AddToLogStore(message); } @@ -554,6 +555,7 @@ public void DebugMessage(string message) /// Message we'd like shown in console. public void SystemDebugMessage(string message) { + message = FormatMessage(message); Messages.Enqueue(new SystemDebugPacket(_job.ProjectId, AlgorithmId, CompileId, message)); AddToLogStore(message); } @@ -568,6 +570,7 @@ public void LogMessage(string message) { //Send the logging messages out immediately for live trading: if (Messages.Count > 500) return; + message = FormatMessage(message); Messages.Enqueue(new LogPacket(AlgorithmId, message)); AddToLogStore(message); } @@ -580,6 +583,7 @@ public void LogMessage(string message) public void ErrorMessage(string message, string stacktrace = "") { if (Messages.Count > 500) return; + message = FormatMessage(message); Messages.Enqueue(new HandledErrorPacket(AlgorithmId, message, stacktrace)); AddToLogStore(message + (!string.IsNullOrEmpty(stacktrace) ? ": StackTrace: " + stacktrace : string.Empty)); } @@ -591,6 +595,7 @@ public void ErrorMessage(string message, string stacktrace = "") /// Associated error stack trace. public virtual void RuntimeError(string message, string stacktrace = "") { + message = FormatMessage(message); Messages.Enqueue(new RuntimeErrorPacket(_job.UserId, AlgorithmId, message, stacktrace)); AddToLogStore(message + (!string.IsNullOrEmpty(stacktrace) ? ": StackTrace: " + stacktrace : string.Empty)); SetAlgorithmState(message, stacktrace); diff --git a/Tests/Engine/Results/LiveTradingResultHandlerTests.cs b/Tests/Engine/Results/LiveTradingResultHandlerTests.cs index ba3da3aac2d1..7dd67c61bbb6 100644 --- a/Tests/Engine/Results/LiveTradingResultHandlerTests.cs +++ b/Tests/Engine/Results/LiveTradingResultHandlerTests.cs @@ -27,6 +27,7 @@ using QuantConnect.Lean.Engine.TransactionHandlers; using QuantConnect.Tests.Common.Data.UniverseSelection; using QuantConnect.Data.Custom.IconicTypes; +using System.Collections.Generic; namespace QuantConnect.Tests.Engine.Results { @@ -190,6 +191,37 @@ public void DailySampleValueBasedOnMarketHour(bool extendedMarketHoursEnabled) } } + [Test] + public void MessagesArePrefixedWithAlgorithmTime() + { + using var messaging = new QuantConnect.Messaging.Messaging(); + var result = new LiveTradingResultHandler(); + result.Initialize(new(new LiveNodePacket(), messaging, null, new BacktestingTransactionHandler(), null)); + + var algorithm = new AlgorithmStub(); + algorithm.AddEquity("SPY"); + algorithm.SetDateTime(new DateTime(2026, 1, 15, 9, 30, 0)); + result.SetAlgorithm(algorithm, 10); + + var algorithmTimePrefix = algorithm.Time.ToStringInvariant(DateFormat.UI); + + result.Messages.Clear(); + result.DebugMessage("debug message"); + result.LogMessage("log message"); + result.ErrorMessage("error message"); + result.RuntimeError("runtime message"); + + var messages = new List() + { + result.Messages.OfType().Single().Message, + result.Messages.OfType().Single().Message, + result.Messages.OfType().Single().Message, + result.Messages.OfType().Single().Message + }; + + Assert.That(messages, Has.All.StartsWith(algorithmTimePrefix)); + } + private class TestDataFeed : IDataFeed { public bool IsActive { get; }