Unexpected additional orders created/rejected

cnimativ

Hi All,

Trying to port a simple volatility based strategy from Excel to Backtrader and I ran into some very unexpected behaviors regarding order creation/execution. Specifically, sometimes the orders are created twice in a given day with the first one executed and the second order cancelled/rejected?

Here's the log output:

2006-07-18, VIX: 17.74, VIX_VXV:1.03 SPY Order Canceled/Margin/Rejected, 96 shares
Ref: 17069
OrdType: 0
OrdType: Buy
Status: 7
Status: Margin
Size: 96
Price: 98.75
Price Limit: None
TrailAmount: None
TrailPercent: None
ExecType: 0
ExecType: Market
CommInfo: None
End of Session: 732509.9999999999
Info: AutoOrderedDict()
Broker: None
Alive: False
2007-05-17, VIX: 13.51, VIX_VXV:0.95 SPY SELL EXECUTED, -1 shares at 122.89
2007-05-17, VIX: 13.51, VIX_VXV:0.95 SPY SELL EXECUTED, -1 shares at 122.89

Here's the code


class vix_ratio(bt.Strategy):

    def log(self, txt):
        print("%s, VIX: %.2f, VIX_VXV:%.2f %s" % (self.vix.datetime.date(0).isoformat(), self.vix.close[0], self.vix_ratio, txt))       
              
    def __init__(self):
        self.vix_ratio = 0
        
        self.spy = self.data0
        self.agg = self.data1
        self.vix = self.data2
        self.vxv = self.data3
        return None
    
    def notify_order(self, order):
        if order.status in [order.Submitted, order.Accepted]:
            # Buy/Sell order submitted/accepted to/by broker - Nothing to do
            return
        
        # Check if an order has been completed
        # Attention: broker could reject order if not enougth cash
        if order.status in [order.Completed]:
            if order.isbuy():
                self.log(order.data._name + ' BUY EXECUTED, %.0f shares at $%.2f' % (order.size, order.executed.price))
            elif order.issell():
                self.log(order.data._name + ' SELL EXECUTED, %.0f shares at %.2f' % (order.size, order.executed.price))

            self.bar_executed = len(self)

        elif order.status in [order.Canceled, order.Margin, order.Rejected]:
            self.log(order.data._name + ' Order Canceled/Margin/Rejected, %.0f shares' % (order.size))#, order.price))
            print(order)
        # Write down: no pending order
        self.order = None
        
    def next(self):
        #print(self.sma1[0], self.sma2[0])
        self.vix_ratio = self.vix.close[0]/self.vxv.close[0]
        
        if self.vix_ratio > 1 and self.vix.close[0] > 20:
            self.order = self.order_target_percent(data=self.spy, target=0)
            self.order = self.order_target_percent(data=self.agg, target=0.99)
        else: 
            self.order = self.order_target_percent(data=self.agg, target=0)
            self.order = self.order_target_percent(data=self.spy, target=0.99)
                
def run_strat():
    start = datetime(2006,7,17)
    end = datetime(2017,4,21)   
    
    spy = btfeeds.YahooFinanceData(dataname="SPY", fromdate=start, todate=end)
    agg = btfeeds.YahooFinanceData(dataname="AGG", fromdate=start, todate=end)
    vix = bt.feeds.PandasData(dataname=web.DataReader("^VIX", 'yahoo', start, end), name='VIX')
    vxv = bt.feeds.PandasData(dataname=web.DataReader("^VXV", 'yahoo', start, end), name='VXV')
    
    cerebro = bt.Cerebro(runonce=False)
    
    cerebro.adddata(spy, name="SPY")
    cerebro.adddata(agg, name="AGG")
    cerebro.adddata(vix, name="VIX")
    cerebro.adddata(vxv, name="VXV")
    
    cerebro.addstrategy(vix_ratio)
    cerebro.broker.setcash(10000.0)
    cerebro.addanalyzer(bt.analyzers.PyFolio, _name='pyfolio')
    
    results = cerebro.run()

backtrader

Since you have 4 assets, the most probable reasons for the multiple order generation is that those assets are not aligned in time. That means that next is called and the assets which have not progressed in time, don't move.

Since you have no sentinel in the form of checking the length of the data feed or if an order is pending on that asset, or if you are in the market with that asset, you issue the order again because the conditions are met.

The rejection is probably due to the lack of cash.

In any case it would also seem the log is really odd, because 2006-07-18 comes before 2007-05-17. It might be the web reader gives you the yahoo data in the wrong order.

cnimativ

@backtrader
Okay. I changed the code to using the new cheat_on_open param and loaded the data using backtrader internal btfeeds. With the new cheat_on_open combined with order_target_percent, the model shouldn't be out of cash. And w/ import backtrader.feeds as btfeeds, it should take care of data alignment problem. I've also made sure I place order_target_percent(target = 0) ahead of order_target_percent(target = 1) so I never buy before I sell.

With these above feature combined, I shouldn't be getting get order rejected/margin/etc errors. But I am still getting those, big time, throwing the whole backtest result off.

But I am still getting a whole lot of errors on trade log errors. Here are the first several lines:

2006-07-18, VIX: 17.74, VIX_VXV:1.03 SPY BUY EXECUTED, 100 shares at $99.04
2007-07-26, VIX: 20.74, VIX_VXV:1.09 AGG Order Canceled/Margin/Rejected, 171 shares
2007-07-26, VIX: 20.74, VIX_VXV:1.09 SPY SELL EXECUTED, -100 shares at 122.45
2007-09-18, VIX: 20.35, VIX_VXV:0.99 SPY BUY EXECUTED, 99 shares at $121.34
2007-10-22, VIX: 21.64, VIX_VXV:1.01 SPY SELL EXECUTED, -99 shares at 121.94
2007-10-22, VIX: 21.64, VIX_VXV:1.01 AGG Order Canceled/Margin/Rejected, 166 shares
2007-10-23, VIX: 20.41, VIX_VXV:0.97 SPY BUY EXECUTED, 99 shares at $124.07
2007-11-01, VIX: 23.21, VIX_VXV:1.03 AGG Order Canceled/Margin/Rejected, 168 shares
2007-11-01, VIX: 23.21, VIX_VXV:1.03 SPY SELL EXECUTED, -99 shares at 125.57
2007-11-02, VIX: 23.01, VIX_VXV:0.99 SPY BUY EXECUTED, 101 shares at $124.13
2007-11-05, VIX: 24.31, VIX_VXV:1.01 AGG Order Canceled/Margin/Rejected, 167 shares
2007-11-05, VIX: 24.31, VIX_VXV:1.01 SPY SELL EXECUTED, -101 shares at 122.58
2007-11-06, VIX: 21.39, VIX_VXV:0.96 SPY BUY EXECUTED, 99 shares at $123.58
2007-11-07, VIX: 26.49, VIX_VXV:1.05 AGG Order Canceled/Margin/Rejected, 166 shares

The full code is as follows, run on Jupyter Notebook.

import backtrader as bt
import backtrader.feeds as btfeeds
from datetime import datetime
import pandas_datareader.data as web
import matplotlib.pylab as pylab
pylab.rcParams['figure.figsize'] = 20, 10  # that's default image size for this interactive session
pylab.rcParams["font.size"] = "20"

class vix_ratio(bt.Strategy):

    def log(self, txt):
        print("%s, VIX: %.2f, VIX_VXV:%.2f %s" % (self.vix.datetime.date(0).isoformat(), self.vix.close[0], self.vix_ratio, txt))       
              
    def __init__(self):
        self.spy = self.data0
        self.agg = self.data1
        self.vix = self.data2
        self.vxv = self.data3
        self.vix_ratio = 0
        self.flag = True
    
    def notify_order(self, order):
        if order.status in [order.Submitted, order.Accepted]:
            # Buy/Sell order submitted/accepted to/by broker - Nothing to do
            return
        
        # Check if an order has been completed
        # Attention: broker could reject order if not enougth cash
        if order.status in [order.Completed]:
            if order.isbuy():
                self.log(order.data._name + ' BUY EXECUTED, %.0f shares at $%.2f' % (order.size, order.executed.price))
            elif order.issell():
                self.log(order.data._name + ' SELL EXECUTED, %.0f shares at %.2f' % (order.size, order.executed.price))

            self.bar_executed = len(self)

        elif order.status in [order.Canceled, order.Margin, order.Rejected]:
            self.log(order.data._name + ' Order Canceled/Margin/Rejected, %.0f shares' % (order.size))
        # Write down: no pending order
        self.order = None
        
    def next_open(self): # Using cheat-on-open
        self.vix_ratio = self.vix.close[0]/self.vxv.close[0]
        
        if (self.vix_ratio <= 1 or self.vix.close[0] <= 20) and self.flag:
            self.flag = False
            self.order = self.order_target_percent(data=self.agg, target=0)
            self.order = self.order_target_percent(data=self.spy, target=1)
        elif (self.vix_ratio > 1 and self.vix.close[0] > 20) and not self.flag:
            self.flag = True
            self.order = self.order_target_percent(data=self.spy, target=0)
            self.order = self.order_target_percent(data=self.agg, target=1)
            
def run_strat():
    start = datetime(2006,7,17)
    end = datetime(2017,4,21)   
    
    spy = btfeeds.YahooFinanceData(dataname="SPY", fromdate=start, todate=end)
    agg = btfeeds.YahooFinanceData(dataname="AGG", fromdate=start, todate=end)
    vix = btfeeds.YahooFinanceData(dataname="^VIX", fromdate=start, todate=end)
    vxv = btfeeds.YahooFinanceData(dataname="^VXV", fromdate=start, todate=end)
    
    cerebro = bt.Cerebro(cheat_on_open=True)
    
    cerebro.adddata(spy, name="SPY")
    cerebro.adddata(agg, name="AGG")
    cerebro.adddata(vix, name="VIX")
    cerebro.adddata(vxv, name="VXV")
    
    cerebro.addstrategy(vix_ratio)
    cerebro.broker.setcash(10000.0)
    
    results = cerebro.run()        
    cerebro.plot()

if __name__ == '__main__':
    run_strat()

backtrader

You are still using the close price for the calculation of the stake, which may be significantly different of the open. If you don't specifically specify the opening price it will not be used for the calculation. The calculation of the percent doesn't know you are cheating and are able to act before the broker.

cnimativ

Here's the log if I print out the orders when they got canceled/margin/rejected.

On 2006-07-18, it bought 100 shares of SPY at $99.04, for $9904, with $96 cash left.

On 2007-07-26, it sold 100 shares of SPY at $122.45, account balance should be $12,245 + prior cash of $96, and broker.getcash() reports $12,341. So selling w/ order_target_percent had no problem to sell at open with cheat_on_open.

But then the problem came. It turns around and buys 171 shares of AGG for $72.45 for $12,388.95, which is greater than $12,341 account value and got rejected. Thus the rejection. Which means, order_target_percent with cheat_on_open does not work for allocation trades.

Two bugs here:

Since the notify_order logged buying AGG before selling SPY, It could be that if we used order_target_percent sizer, the trade ordering will be mixed up and backtrader ends up placing buy before sell.
On the other hand, the order_target_percent sizer also did not size AGG properly if we look at the account values alone. It seemed to be using prior close of SPY ($123.61) to calculate account value. Previous close is $123.61 x 100 shares + $91 cash = $12452 account value > $12388.95, which can buy at max 171 share of AGG at $72.45. But in reality, backtrader order_target_percent sizer with cheat_on_open needs to be and should only be calculating account size using Open only. Never previous close.

2006-07-18, VIX: 17.74, VIX_VXV:1.03 SPY BUY EXECUTED, 100 shares at $99.04
2007-07-26, VIX: 20.74, VIX_VXV:1.09 AGG Order Canceled/Margin/Rejected, 171 shares
12341.0
123.61
Ref: 13711
OrdType: 0
OrdType: Buy
Status: 7
Status: Margin
Size: 171
Price: 72.47
Price Limit: None
TrailAmount: None
TrailPercent: None
ExecType: 0
ExecType: Market
CommInfo: None
End of Session: 732883.9999999999
Info: AutoOrderedDict()
Broker: None
Alive: False
2007-07-26, VIX: 20.74, VIX_VXV:1.09 SPY SELL EXECUTED, -100 shares at 122.45
2007-09-18, VIX: 20.35, VIX_VXV:0.99 SPY BUY EXECUTED, 99 shares at $121.34
2007-10-22, VIX: 21.64, VIX_VXV:1.01 SPY SELL EXECUTED, -99 shares at 121.94
2007-10-22, VIX: 21.64, VIX_VXV:1.01 AGG Order Canceled/Margin/Rejected, 166 shares
12400.4
Ref: 13714
OrdType: 0
OrdType: Buy
Status: 7
Status: Margin
Size: 166
Price: 74.8
Price Limit: None
TrailAmount: None
TrailPercent: None
ExecType: 0
ExecType: Market
CommInfo: None
End of Session: 732971.9999999999
Info: AutoOrderedDict()
Broker: None
Alive: False
2007-10-23, VIX: 20.41, VIX_VXV:0.97 SPY BUY EXECUTED, 99 shares at $124.07
2007-11-01, VIX: 23.21, VIX_VXV:1.03 AGG Order Canceled/Margin/Rejected, 168 shares
12548.9
Ref: 13717
OrdType: 0
OrdType: Buy
Status: 7
Status: Margin
Size: 168
Price: 74.92
Price Limit: None
TrailAmount: None
TrailPercent: None
ExecType: 0
ExecType: Market
CommInfo: None
End of Session: 732981.9999999999
Info: AutoOrderedDict()
Broker: None
Alive: False
2007-11-01, VIX: 23.21, VIX_VXV:1.03 SPY SELL EXECUTED, -99 shares at 125.57
2007-11-02, VIX: 23.01, VIX_VXV:0.99 SPY BUY EXECUTED, 101 shares at $124.13
2007-11-05, VIX: 24.31, VIX_VXV:1.01 AGG Order Canceled/Margin/Rejected, 167 shares
12392.35
Ref: 13720
OrdType: 0
OrdType: Buy
Status: 7
Status: Margin
Size: 167
Price: 74.93
Price Limit: None
TrailAmount: None
TrailPercent: None
ExecType: 0
ExecType: Market
CommInfo: None
End of Session: 732985.9999999999
Info: AutoOrderedDict()
Broker: None
Alive: False
2007-11-05, VIX: 24.31, VIX_VXV:1.01 SPY SELL EXECUTED, -101 shares at 122.58
2007-11-06, VIX: 21.39, VIX_VXV:0.96 SPY BUY EXECUTED, 99 shares at $123.58
2007-11-07, VIX: 26.49, VIX_VXV:1.05 AGG Order Canceled/Margin/Rejected, 166 shares
12358.69
Ref: 13723
OrdType: 0
OrdType: Buy
Status: 7
Status: Margin
Size: 166
Price: 74.85
Price Limit: None
TrailAmount: None
TrailPercent: None
ExecType: 0
ExecType: Market
CommInfo: None
End of Session: 732987.9999999999
Info: AutoOrderedDict()
Broker: None
Alive: False
2007-11-07, VIX: 26.49, VIX_VXV:1.05 SPY SELL EXECUTED, -99 shares at 123.24
2007-11-13, VIX: 24.10, VIX_VXV:0.98 SPY BUY EXECUTED, 101 shares at $119.08
2007-11-14, VIX: 25.94, VIX_VXV:1.01 SPY SELL EXECUTED, -101 shares at 122.24

Here's the code that produces these two bugs:

import backtrader as bt
import backtrader.feeds as btfeeds
from datetime import datetime
import pandas_datareader.data as web
import matplotlib.pylab as pylab
pylab.rcParams['figure.figsize'] = 20, 10  # that's default image size for this interactive session
pylab.rcParams["font.size"] = "20"

class vix_ratio(bt.Strategy):

    def log(self, txt):
        print("%s, VIX: %.2f, VIX_VXV:%.2f %s" % (self.vix.datetime.date(0).isoformat(), self.vix.close[0], self.vix_ratio, txt))       
              
    def __init__(self):
        self.spy = self.data0
        self.agg = self.data1
        self.vix = self.data2
        self.vxv = self.data3
        self.vix_ratio = 0
        self.flag = True
    
    def notify_order(self, order):
        if order.status in [order.Submitted, order.Accepted]:
            # Buy/Sell order submitted/accepted to/by broker - Nothing to do
            return
        
        # Check if an order has been completed
        # Attention: broker could reject order if not enougth cash
        if order.status in [order.Completed]:
            if order.isbuy():
                self.log(order.data._name + ' BUY EXECUTED, %.0f shares at $%.2f' % (order.size, order.executed.price))
            elif order.issell():
                self.log(order.data._name + ' SELL EXECUTED, %.0f shares at %.2f' % (order.size, order.executed.price))

            self.bar_executed = len(self)

        elif order.status in [order.Canceled, order.Margin, order.Rejected]:
            self.log(order.data._name + ' Order Canceled/Margin/Rejected, %.0f shares' % (order.size))#, order.price))
            print(self.broker.getcash())
            print(self.spy[-1])
            print(order)
        # Write down: no pending order
        self.order = None
        
    def next_open(self): # Using cheat-on-open
        self.vix_ratio = self.vix.close[0]/self.vxv.close[0]
        
        if (self.vix_ratio <= 1 or self.vix.close[0] <= 20) and self.flag:
            self.flag = False
            self.order = self.order_target_percent(data=self.agg, target=0)
            self.order = self.order_target_percent(data=self.spy, target=1)
        elif (self.vix_ratio > 1 and self.vix.close[0] > 20) and not self.flag:
            self.flag = True
            self.order = self.order_target_percent(data=self.spy, target=0)
            self.order = self.order_target_percent(data=self.agg, target=1)
            
def run_strat():
    start = datetime(2006,7,17)
    end = datetime(2017,4,21)   
    
    spy = btfeeds.YahooFinanceData(dataname="SPY", fromdate=start, todate=end)
    agg = btfeeds.YahooFinanceData(dataname="AGG", fromdate=start, todate=end)
    vix = btfeeds.YahooFinanceData(dataname="^VIX", fromdate=start, todate=end)
    vxv = btfeeds.YahooFinanceData(dataname="^VXV", fromdate=start, todate=end)
    #vix = bt.feeds.PandasData(dataname=web.DataReader("^VIX", 'yahoo', start, end), name='VIX')
    #vxv = bt.feeds.PandasData(dataname=web.DataReader("^VXV", 'yahoo', start, end), name='VXV')
    
    cerebro = bt.Cerebro(cheat_on_open=True)
    
    cerebro.adddata(spy, name="SPY")
    cerebro.adddata(agg, name="AGG")
    cerebro.adddata(vix, name="VIX")
    cerebro.adddata(vxv, name="VXV")
    
    cerebro.addstrategy(vix_ratio)
    cerebro.broker.setcash(10000.0)
    #cerebro.addanalyzer(bt.analyzers.PyFolio, _name='pyfolio')
    
    results = cerebro.run()
        
    cerebro.plot()
    """strat = results[0]
    pyfoliozer = strat.analyzers.getbyname('pyfolio')
    returns, positions, transactions, gross_lev = pyfoliozer.get_pf_items()

    return returns, positions, transactions
    """
if __name__ == '__main__':
    #r, p, t = run_strat()
    run_strat()

cnimativ

@backtrader

You are still using the close price for the calculation of the stake, which may be significantly different of the open. If you don't specifically specify the opening price it will not be used for the calculation. The calculation of the percent doesn't know you are cheating and are able to act before the broker

So in other words, cheat_on_open doesn't really cheat on open for open_target_percent?

backtrader

From the Blog - Cheat On Open post documenting cheat_on_open

Activates an extra cycle in the system which calls the methods in the strategy next_open, nextstart_open and prenext_open

A lot more could be quoted, but in summary: The post doesn't say anything about order_target_percent. It says it gives you the chance to act before the broker has evaluated the orders and the indicators are recalculated That means it is really giving you an equivalent of acting during the open, before anything happens. You choose what to do.

order_target_percent makes a calculation based on the latest available price unless it is told to use a different price. Because you specify no other price, the latest available price is used. You could also decide to use the high price if wished, but you probably want to use the opening price.

In other words: you have to cheat, the method doesn't.

cnimativ

@backtrader

Got it. Back to spaghetti code try except lookahead.

In your mind, what would be the best way to structure the code for live trading for 100% invested allocation purposes, aside from leaving 1-1.5% cash to make sure everyhing fills?

backtrader

You only have to specify to order_target_percent which price has to be used for the calculation of the stake.

Maybe someone has experience with all-in strategies.

cnimativ

@backtrader
Again, order_target_percent does not work properly. It is always calculating position target value with the wrong basis using the previous close, regardless if you look-ahead or using the new cheat_on_open.

If you look at broker.py line 365 def _get_value(), its very clear that the portfolio values is only calculated at close. order_target_percent thenh calculates account/position value with the current close (see line 1301, strategy.py, target *= self.broker.getvalue()).

What should've happened, for cheat_on_open, is that broker.get_value() should return the value of the account at the current open for calculating sizing but instead it uses previous close for sizing.

It is not obvious if you trade only a single security at 10% sizing but errors will show up all over the place if you trade more than one security with more than 95% of the portfolio invested.

The intellectually lazy way to bypass this bug is to never allocate over 90-95% of the whole portfolio to prevent this problem from showing up. The downside of salvaging backtesting this way is that it is difficult to verify backtrader output verified against Excel or simple vectorized backtests.

backtrader

@cnimativ said in Unexpected additional orders created/rejected:

What should've happened, for cheat_on_open, is that broker.get_value() should return the value of the account at the current open for calculating sizing but instead it uses previous close for sizing.

Wrong assumption. With cheat_on_open you are given the chance to act before the market opens. But the broker cannot calculate the portfolio on prices which have yet to happen, but which are available to your for cheating, because you can already access the new open price.

If the value were to be recalculated with the open price, which has not happened yet, you would actually be given free money (if moving in your direction) to trade with that same open price. That goes beyond to cheating by getting access to the opening price, because it introduces a wrong calculation in the system.

You can still specify the opening price to order_target_percent and your orders will be sized accordingly, because a market order issued before the opening bell will be matched with the open price. But that seems to be the only thing which is not being done: price=self.data.open[0]

cnimativ

@backtrader
? I am already placing trade w/ price=self.data.open[0] and cheat_on_open. Backtrader will reject those orders internally due to reasons outlined above.

On another thought, how do we place orders on margin? Adding those margin cash will be another way to solve this issue. Does backtrader keep track of gross exposure vs net exposure/unlevered? I can tolerate trading on a few points of margin to get fill in both live/simulation but need a wy to track gross/net exposure.

gabrielfior

@cnimativ Do you have a working solution for this problem, involving order_target_percent and multiple assets? A Jupyter notebook implementation would be excellent. Thank you.