/* * QUANTCONNECT.COM - Democratizing Finance, Empowering Individuals. * Lean Algorithmic Trading Engine v2.0. Copyright 2014 QuantConnect Corporation. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. * */ using System; using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics; using System.IO; using System.Linq; using Newtonsoft.Json; using QuantConnect.Configuration; using QuantConnect.Data; using QuantConnect.Data.UniverseSelection; using QuantConnect.Interfaces; using QuantConnect.Logging; using QuantConnect.Orders; using QuantConnect.Securities; using QuantConnect.Util; namespace QuantConnect.Lean.Engine.Results { /// /// Provides a wrapper over the that logs all order events /// to a separate file /// public class RegressionResultHandler : BacktestingResultHandler { private Language Language => Config.GetValue("algorithm-language"); private DateTime _testStartTime; private DateTime _lastRuntimeStatisticsDate; private TextWriter _writer; private readonly object _sync = new object(); private readonly ConcurrentQueue _preInitializeLines; private readonly Dictionary _currentRuntimeStatistics; private readonly Dictionary _currentAlphaRuntimeStatistics; // this defaults to false since it can create massive files. a full regression run takes about 800MB // for each folder (800MB for ./passed and 800MB for ./regression) private static readonly bool HighFidelityLogging = Config.GetBool("regression-high-fidelity-logging", false); private static readonly bool IsTest = !Process.GetCurrentProcess().ProcessName.Contains("Lean.Launcher"); /// /// Gets the path used for logging all portfolio changing events, such as orders, TPV, daily holdings values /// public string LogFilePath => IsTest ? $"./regression/{AlgorithmId}.{Language.ToLower()}.details.log" : $"./{AlgorithmId}/{DateTime.Now:yyyy-MM-dd-hh-mm-ss}.{Language.ToLower()}.details.log"; /// /// True if there was a runtime error running the algorithm /// public bool HasRuntimeError { get; private set; } /// /// Initializes a new instance of the class /// public RegressionResultHandler() { _testStartTime = DateTime.UtcNow; _preInitializeLines = new ConcurrentQueue(); _currentRuntimeStatistics = new Dictionary(); _currentAlphaRuntimeStatistics = new Dictionary(); } /// /// Initializes the stream writer using the algorithm's id (name) in the file path /// public override void SetAlgorithm(IAlgorithm algorithm, decimal startingPortfolioValue) { base.SetAlgorithm(algorithm, startingPortfolioValue); var fileInfo = new FileInfo(LogFilePath); Directory.CreateDirectory(fileInfo.DirectoryName); if (fileInfo.Exists) { fileInfo.Delete(); } lock (_sync) { _writer = new StreamWriter(LogFilePath); WriteLine($"{_testStartTime}: Starting regression test"); string line; while (_preInitializeLines.TryDequeue(out line)) { WriteLine(line); } } } /// /// Runs on date changes, use this to log TPV and holdings values each day /// protected override void SamplePerformance(DateTime time, decimal value) { lock (_sync) { WriteLine($"{Algorithm.UtcTime}: Total Portfolio Value: {Algorithm.Portfolio.TotalPortfolioValue}"); // write the entire cashbook each day, includes current conversion rates and total value of cash holdings WriteLine($"{Environment.NewLine}{Algorithm.Portfolio.CashBook}"); foreach (var kvp in Algorithm.Securities) { var symbol = kvp.Key; var security = kvp.Value; if (!security.HoldStock) { continue; } // detailed logging of security holdings WriteLine( $"{Algorithm.UtcTime}: " + $"Holdings: {symbol.Value} ({symbol.ID}): " + $"Price: {security.Price} " + $"Quantity: {security.Holdings.Quantity} " + $"Value: {security.Holdings.HoldingsValue} " + $"LastData: {security.GetLastData()}" ); } } base.SamplePerformance(time, value); } /// /// Log the order and order event to the dedicated log file for this regression algorithm /// /// In backtesting the order events are not sent because it would generate a high load of messaging. /// New order event details public override void OrderEvent(OrderEvent newEvent) { // log order events to a separate file for easier diffing of regression runs var order = Algorithm.Transactions.GetOrderById(newEvent.OrderId); lock (_sync) { WriteLine("=============================================================="); WriteLine($" Symbol: {order.Symbol}"); WriteLine($" Order: {order}"); WriteLine($" Event: {newEvent}"); WriteLine($" Position: {Algorithm.Portfolio[newEvent.Symbol].Quantity}"); SecurityHolding underlyingHolding; if (newEvent.Symbol.HasUnderlying && Algorithm.Portfolio.TryGetValue(newEvent.Symbol.Underlying, out underlyingHolding)) { WriteLine($"Underlying: {underlyingHolding.Quantity}"); } WriteLine($" Cash: {Algorithm.Portfolio.Cash:0.00}"); WriteLine($" Portfolio: {Algorithm.Portfolio.TotalPortfolioValue:0.00}"); WriteLine("=============================================================="); } base.OrderEvent(newEvent); } /// /// Send list of security asset types the algortihm uses to browser. /// public override void SecurityType(List types) { base.SecurityType(types); var sorted = types.Select(type => type.ToString()).OrderBy(type => type); WriteLine($"SecurityTypes: {string.Join("|", sorted)}"); } /// /// Send a debug message back to the browser console. /// /// Message we'd like shown in console. public override void DebugMessage(string message) { base.DebugMessage(message); WriteLine($"DebugMessage: {message}"); } /// /// Send an error message back to the browser highlighted in red with a stacktrace. /// /// Error message we'd like shown in console. /// Stacktrace information string public override void ErrorMessage(string message, string stacktrace = "") { base.ErrorMessage(message, stacktrace); stacktrace = string.IsNullOrEmpty(stacktrace) ? null : Environment.NewLine + stacktrace; WriteLine($"ErrorMessage: {message}{stacktrace}"); } /// /// Send a logging message to the log list for storage. /// /// Message we'd in the log. public override void LogMessage(string message) { base.LogMessage(message); WriteLine($"LogMessage: {message}"); } /// /// Send a runtime error message back to the browser highlighted with in red /// /// Error message. /// Stacktrace information string public override void RuntimeError(string message, string stacktrace = "") { HasRuntimeError = true; base.RuntimeError(message, stacktrace); stacktrace = string.IsNullOrEmpty(stacktrace) ? null : Environment.NewLine + stacktrace; WriteLine($"RuntimeError: {message}{stacktrace}"); } /// /// Send a system debug message back to the browser console. /// /// Message we'd like shown in console. public override void SystemDebugMessage(string message) { base.SystemDebugMessage(message); WriteLine($"SystemDebugMessage: {message}"); } /// /// Set the current runtime statistics of the algorithm. /// These are banner/title statistics which show at the top of the live trading results. /// /// Runtime headline statistic name /// Runtime headline statistic value public override void RuntimeStatistic(string key, string value) { try { if (HighFidelityLogging || _lastRuntimeStatisticsDate != Algorithm.Time.Date) { _lastRuntimeStatisticsDate = Algorithm.Time.Date; string existingValue; if (!_currentRuntimeStatistics.TryGetValue(key, out existingValue) || existingValue != value) { _currentRuntimeStatistics[key] = value; WriteLine($"RuntimeStatistic: {key}: {value}"); } } base.RuntimeStatistic(key, value); } catch (Exception exception) { Log.Error(exception); } } /// /// Save an algorithm message to the log store. Uses a different timestamped method of adding messaging to interweve debug and logging messages. /// /// String message to store protected override void AddToLogStore(string message) { base.AddToLogStore(message); WriteLine($"AddToLogStore: {message}"); } /// /// Event fired each time that we add/remove securities from the data feed /// public override void OnSecuritiesChanged(SecurityChanges changes) { base.OnSecuritiesChanged(changes); if (changes.AddedSecurities.Count > 0) { var added = changes.AddedSecurities .Select(security => security.Symbol.ToString()) .OrderBy(symbol => symbol); WriteLine($"OnSecuritiesChanged:ADD: {string.Join("|", added)}"); } if (changes.RemovedSecurities.Count > 0) { var removed = changes.RemovedSecurities .Select(security => security.Symbol.ToString()) .OrderBy(symbol => symbol); WriteLine($"OnSecuritiesChanged:REM: {string.Join("|", removed)}"); } } /// /// Runs at the end of each time loop. When HighFidelityLogging is enabled, we'll /// log each piece of data to allow for faster determination of regression causes /// public override void ProcessSynchronousEvents(bool forceProcess = false) { if (HighFidelityLogging) { var slice = Algorithm.CurrentSlice; if (slice != null) { lock (_sync) { // aggregate slice data WriteLine($"Slice Time: {slice.Time:o} Slice Count: {slice.Count}"); var data = new Dictionary>(); foreach (var kvp in slice.Bars) { data.Add(kvp.Key, (BaseData) kvp.Value); } foreach (var kvp in slice.QuoteBars) { data.Add(kvp.Key, (BaseData)kvp.Value); } foreach (var kvp in slice.Ticks) { foreach (var tick in kvp.Value) { data.Add(kvp.Key, (BaseData) tick); } } foreach (var kvp in slice.Delistings) { data.Add(kvp.Key, (BaseData) kvp.Value); } foreach (var kvp in slice.Splits) { data.Add(kvp.Key, (BaseData) kvp.Value); } foreach (var kvp in slice.SymbolChangedEvents) { data.Add(kvp.Key, (BaseData) kvp.Value); } foreach (var kvp in slice.Dividends) { data.Add(kvp.Key, (BaseData) kvp.Value); } foreach (var kvp in data.OrderBy(kvp => kvp.Key)) { foreach (var item in kvp.Value) { WriteLine($"{Algorithm.UtcTime}: Slice: DataTime: {item.EndTime} {item}"); } } } } } base.ProcessSynchronousEvents(forceProcess); } /// /// Save the results to disk /// public override void SaveResults(string name, Result result) { File.WriteAllText(GetResultsPath(name), JsonConvert.SerializeObject(result)); } /// /// Terminate the result thread and apply any required exit procedures. /// Save orders log files to disk. /// public override void Exit() { if (!ExitTriggered && Algorithm != null) { var holdings = Algorithm.Portfolio.Values.Where(holding => holding.Invested).Select(holding => $"HOLDINGS:: {holding}").ToList(); if(holdings.Count > 0) { Log.Trace($"{Environment.NewLine}{string.Join(Environment.NewLine, holdings)}"); } else { Log.Trace("HOLDINGS:: none"); } Log.Trace($"{Environment.NewLine}{Algorithm.Portfolio.CashBook}"); } base.Exit(); lock (_sync) { if (_writer != null) { // only log final statistics and we want them to all be together foreach (var kvp in RuntimeStatistics.OrderBy(kvp => kvp.Key)) { WriteLine($"{kvp.Key,-15}\t{kvp.Value}"); } var end = DateTime.UtcNow; var delta = end - _testStartTime; WriteLine($"{end}: Completed regression test, took: {delta.TotalSeconds:0.0} seconds"); _writer.DisposeSafely(); _writer = null; } else { string line; while (_preInitializeLines.TryDequeue(out line)) { Console.WriteLine(line); } } } } /// /// We want to make algorithm messages end up in both the standard regression log file {algorithm}.{language}.log /// as well as the details log {algorithm}.{language}.details.log. The details log is focused on providing a log /// dedicated solely to the algorithm's behavior, void of all messages /// protected override void ConfigureConsoleTextWriter(IAlgorithm algorithm) { // configure Console.WriteLine and Console.Error.WriteLine to both logs, syslog and details.log // when 'forward-console-messages' is set to false, it guarantees synchronous logging of these messages if (Config.GetBool("forward-console-messages", true)) { // we need to forward Console.Write messages to the algorithm's Debug function Console.SetOut(new FuncTextWriter(msg => { algorithm.Debug(msg); WriteLine($"DEBUG: {msg}"); })); Console.SetError(new FuncTextWriter(msg => { algorithm.Error(msg); WriteLine($"ERROR: {msg}"); })); } else { // we need to forward Console.Write messages to the standard Log functions Console.SetOut(new FuncTextWriter(msg => { Log.Trace(msg); WriteLine($"DEBUG: {msg}"); })); Console.SetError(new FuncTextWriter(msg => { Log.Error(msg); WriteLine($"ERROR: {msg}"); })); } } private void WriteLine(string message) { if (!Log.DebuggingEnabled) { return; } lock (_sync) { if (_writer == null) { _preInitializeLines.Enqueue(message); } else { _writer.WriteLine($"{Algorithm.Time:O}: {message}"); } } } } }