Skip to content

Commit 9a42304

Browse files
JosueNinaJosueNina
committed
Prefix all algorithm logs and messages with IAlgorithm.Time
1 parent 02d0dfa commit 9a42304

6 files changed

Lines changed: 71 additions & 6 deletions

File tree

‎Algorithm/QCAlgorithm.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3817,7 +3817,7 @@ private DateTime GetTimeInExchangeTimeZone(Symbol symbol)
38173817

38183818
private string FormatLog(string message)
38193819
{
3820-
return $"{Time.ToStringInvariant(DateFormat.UI)} {message}";
3820+
return message.PrefixWithAlgorithmTime(Time);
38213821
}
38223822
}
38233823
}

‎Common/Extensions.cs‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -79,6 +79,18 @@ public static class Extensions
7979
private static readonly Dictionary<IntPtr, PythonActivator> PythonActivators
8080
= new Dictionary<IntPtr, PythonActivator>();
8181

82+
/// <summary>
83+
/// Prefixes the given message with the provided algorithm time, producing the standard
84+
/// timestamped format shared by algorithm logs and messages
85+
/// </summary>
86+
/// <param name="message">The message to prefix</param>
87+
/// <param name="algorithmTime">The algorithm time to prefix the message with</param>
88+
/// <returns>The message prefixed with the algorithm time</returns>
89+
public static string PrefixWithAlgorithmTime(this string message, DateTime algorithmTime)
90+
{
91+
return $"{algorithmTime.ToStringInvariant(DateFormat.UI)} {message}";
92+
}
93+
8294
/// <summary>
8395
/// Maintains old behavior of NodaTime's (&lt; 2.0) daylight savings mapping.
8496
/// We keep the old behavior to ensure the FillForwardEnumerator does not get stuck on an infinite loop.

‎Engine/Results/BacktestingResultHandler.cs‎

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -469,6 +469,7 @@ public override void SetAlgorithm(IAlgorithm algorithm, decimal startingPortfoli
469469
/// <param name="message">Message we'd like shown in console.</param>
470470
public virtual void DebugMessage(string message)
471471
{
472+
message = FormatMessage(message);
472473
Messages.Enqueue(new DebugPacket(_projectId, AlgorithmId, CompileId, message));
473474
AddToLogStore(message);
474475
}
@@ -479,6 +480,7 @@ public virtual void DebugMessage(string message)
479480
/// <param name="message">Message we'd like shown in console.</param>
480481
public virtual void SystemDebugMessage(string message)
481482
{
483+
message = FormatMessage(message);
482484
Messages.Enqueue(new SystemDebugPacket(_projectId, AlgorithmId, CompileId, message));
483485
AddToLogStore(message);
484486
}
@@ -489,6 +491,7 @@ public virtual void SystemDebugMessage(string message)
489491
/// <param name="message">Message we'd in the log.</param>
490492
public virtual void LogMessage(string message)
491493
{
494+
message = FormatMessage(message);
492495
Messages.Enqueue(new LogPacket(AlgorithmId, message));
493496
AddToLogStore(message);
494497
}
@@ -502,8 +505,8 @@ public virtual void ErrorMessage(string message, string stacktrace = "")
502505
{
503506
if (message == _errorMessage) return;
504507
if (Messages.Count > 500) return;
505-
Messages.Enqueue(new HandledErrorPacket(AlgorithmId, message, stacktrace));
506508
_errorMessage = message;
509+
Messages.Enqueue(new HandledErrorPacket(AlgorithmId, FormatMessage(message), stacktrace));
507510
}
508511

509512
/// <summary>
@@ -514,8 +517,9 @@ public virtual void ErrorMessage(string message, string stacktrace = "")
514517
public virtual void RuntimeError(string message, string stacktrace = "")
515518
{
516519
PurgeQueue();
517-
Messages.Enqueue(new RuntimeErrorPacket(_job.UserId, AlgorithmId, message, stacktrace));
518520
_errorMessage = message;
521+
message = FormatMessage(message);
522+
Messages.Enqueue(new RuntimeErrorPacket(_job.UserId, AlgorithmId, message, stacktrace));
519523
SetAlgorithmState(message, stacktrace);
520524
}
521525

‎Engine/Results/BaseResultsHandler.cs‎

Lines changed: 13 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1122,6 +1122,18 @@ protected StatisticsResults GenerateStatisticsResults(CapacityEstimate estimated
11221122
return GenerateStatisticsResults(charts, profitLoss, estimatedStrategyCapacity);
11231123
}
11241124

1125+
/// <summary>
1126+
/// Prefixes the given message with the algorithm time, matching the format used by
1127+
/// the algorithm's own log messages (see <see cref="IAlgorithm.Log"/>). Used to normalize
1128+
/// the timestamp across all algorithm logs and messages.
1129+
/// </summary>
1130+
/// <param name="message">The message to format</param>
1131+
/// <returns>The message prefixed with the algorithm time, or the original message if the algorithm is not yet available</returns>
1132+
protected string FormatMessage(string message)
1133+
{
1134+
return Algorithm != null ? message.PrefixWithAlgorithmTime(Algorithm.Time) : message;
1135+
}
1136+
11251137
/// <summary>
11261138
/// Save an algorithm message to the log store. Uses a different timestamped method of adding messaging to interweve debug and logging messages.
11271139
/// </summary>
@@ -1171,7 +1183,7 @@ private void ProcessAlgorithmLogsImpl(ConcurrentQueue<string> concurrentQueue, P
11711183
{
11721184
_packetDroppedWarning = true;
11731185
// 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
1174-
Messages.Enqueue(new HandledErrorPacket(AlgorithmId, "Your algorithm messaging has been rate limited to prevent browser flooding."));
1186+
Messages.Enqueue(new HandledErrorPacket(AlgorithmId, FormatMessage("Your algorithm messaging has been rate limited to prevent browser flooding.")));
11751187
}
11761188
//if too many in the queue already skip the logging and drop the messages
11771189
continue;

‎Engine/Results/LiveTradingResultHandler.cs‎

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -254,8 +254,8 @@ private void Update()
254254

255255
var deltaStatistics = new Dictionary<string, string>();
256256
var orders = new Dictionary<int, Order>(TransactionHandler.Orders);
257-
var complete = new LiveResultPacket(_job, new LiveResult(new LiveResultParameters(chartComplete, orders,
258-
Algorithm.Transactions.TransactionRecord, holdings, Algorithm.Portfolio.CashBook, deltaStatistics,
257+
var complete = new LiveResultPacket(_job, new LiveResult(new LiveResultParameters(chartComplete, orders,
258+
Algorithm.Transactions.TransactionRecord, holdings, Algorithm.Portfolio.CashBook, deltaStatistics,
259259
runtimeStatistics, orderEvents, statistics.TotalPerformance, serverStatistics, state: GetAlgorithmState())));
260260
StoreResult(complete);
261261
_nextChartsUpdate = DateTime.UtcNow.Add(ChartUpdateInterval);
@@ -544,6 +544,7 @@ private IEnumerable<LiveResultPacket> SplitPackets(Dictionary<string, Chart> del
544544
public void DebugMessage(string message)
545545
{
546546
if (Messages.Count > 500) return; //if too many in the queue already skip the logging.
547+
message = FormatMessage(message);
547548
Messages.Enqueue(new DebugPacket(_job.ProjectId, AlgorithmId, CompileId, message));
548549
AddToLogStore(message);
549550
}
@@ -554,6 +555,7 @@ public void DebugMessage(string message)
554555
/// <param name="message">Message we'd like shown in console.</param>
555556
public void SystemDebugMessage(string message)
556557
{
558+
message = FormatMessage(message);
557559
Messages.Enqueue(new SystemDebugPacket(_job.ProjectId, AlgorithmId, CompileId, message));
558560
AddToLogStore(message);
559561
}
@@ -568,6 +570,7 @@ public void LogMessage(string message)
568570
{
569571
//Send the logging messages out immediately for live trading:
570572
if (Messages.Count > 500) return;
573+
message = FormatMessage(message);
571574
Messages.Enqueue(new LogPacket(AlgorithmId, message));
572575
AddToLogStore(message);
573576
}
@@ -580,6 +583,7 @@ public void LogMessage(string message)
580583
public void ErrorMessage(string message, string stacktrace = "")
581584
{
582585
if (Messages.Count > 500) return;
586+
message = FormatMessage(message);
583587
Messages.Enqueue(new HandledErrorPacket(AlgorithmId, message, stacktrace));
584588
AddToLogStore(message + (!string.IsNullOrEmpty(stacktrace) ? ": StackTrace: " + stacktrace : string.Empty));
585589
}
@@ -591,6 +595,7 @@ public void ErrorMessage(string message, string stacktrace = "")
591595
/// <param name="stacktrace">Associated error stack trace.</param>
592596
public virtual void RuntimeError(string message, string stacktrace = "")
593597
{
598+
message = FormatMessage(message);
594599
Messages.Enqueue(new RuntimeErrorPacket(_job.UserId, AlgorithmId, message, stacktrace));
595600
AddToLogStore(message + (!string.IsNullOrEmpty(stacktrace) ? ": StackTrace: " + stacktrace : string.Empty));
596601
SetAlgorithmState(message, stacktrace);

‎Tests/Engine/Results/LiveTradingResultHandlerTests.cs‎

Lines changed: 32 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,7 @@
2727
using QuantConnect.Lean.Engine.TransactionHandlers;
2828
using QuantConnect.Tests.Common.Data.UniverseSelection;
2929
using QuantConnect.Data.Custom.IconicTypes;
30+
using System.Collections.Generic;
3031

3132
namespace QuantConnect.Tests.Engine.Results
3233
{
@@ -190,6 +191,37 @@ public void DailySampleValueBasedOnMarketHour(bool extendedMarketHoursEnabled)
190191
}
191192
}
192193

194+
[Test]
195+
public void MessagesArePrefixedWithAlgorithmTime()
196+
{
197+
using var messaging = new QuantConnect.Messaging.Messaging();
198+
var result = new LiveTradingResultHandler();
199+
result.Initialize(new(new LiveNodePacket(), messaging, null, new BacktestingTransactionHandler(), null));
200+
201+
var algorithm = new AlgorithmStub();
202+
algorithm.AddEquity("SPY");
203+
algorithm.SetDateTime(new DateTime(2026, 1, 15, 9, 30, 0));
204+
result.SetAlgorithm(algorithm, 10);
205+
206+
var algorithmTimePrefix = algorithm.Time.ToStringInvariant(DateFormat.UI);
207+
208+
result.Messages.Clear();
209+
result.DebugMessage("debug message");
210+
result.LogMessage("log message");
211+
result.ErrorMessage("error message");
212+
result.RuntimeError("runtime message");
213+
214+
var messages = new List<string>()
215+
{
216+
result.Messages.OfType<DebugPacket>().Single().Message,
217+
result.Messages.OfType<LogPacket>().Single().Message,
218+
result.Messages.OfType<HandledErrorPacket>().Single().Message,
219+
result.Messages.OfType<RuntimeErrorPacket>().Single().Message
220+
};
221+
222+
Assert.That(messages, Has.All.StartsWith(algorithmTimePrefix));
223+
}
224+
193225
private class TestDataFeed : IDataFeed
194226
{
195227
public bool IsActive { get; }

0 commit comments

Comments
 (0)