/*
* 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}");
}
}
}
}
}