Skip to content
This repository has been archived by the owner on Nov 26, 2022. It is now read-only.

Completed orders on Binance & Poloniex are sometimes being reported as perpetually "not filled" by exchange_blotter #178

Closed
briannewtonpsyd opened this issue Jan 22, 2018 · 48 comments

Comments

@briannewtonpsyd
Copy link

Dear Catalyst Maintainers,

Before I tell you about my issue, let me describe my environment:

Environment

  • Operating System: Windows 10
  • Python Version: Python 2.7.13 :: Anaconda 4.4.0 (64-bit)
  • Python Bitness: Command fails
  • How did you install Catalyst: Conda
  • Python packages:
alembic                   0.9.6                     <pip>
backports.functools-lru-cache 1.4                       <pip>
bcolz                     0.12.1                    <pip>
boto3                     1.5.19                    <pip>
botocore                  1.8.33                    <pip>
Bottleneck                1.2.1                     <pip>
ca-certificates           2017.08.26           h94faf87_0
ccxt                      1.10.774                  <pip>
certifi                   2016.2.28                py27_0
certifi                   2018.1.18                 <pip>
chardet                   3.0.4                     <pip>
click                     6.7                       <pip>
contextlib2               0.5.5                     <pip>
cycler                    0.10.0                    <pip>
cyordereddict             1.0.0                     <pip>
Cython                    0.27.1                    <pip>
decorator                 4.1.2                     <pip>
docutils                  0.14                      <pip>
empyrical                 0.2.1                     <pip>
enigma-catalyst           0.4.7                     <pip>
futures                   3.2.0                     <pip>
idna                      2.6                       <pip>
intervaltree              2.1.0                     <pip>
jmespath                  0.9.3                     <pip>
Logbook                   1.1.0                     <pip>
lru-dict                  1.1.6                     <pip>
Mako                      1.0.7                     <pip>
MarkupSafe                1.0                       <pip>
matplotlib                2.1.0                     <pip>
mkl                       2017.0.3                      0
multipledispatch          0.4.9                     <pip>
networkx                  2.0                       <pip>
numexpr                   2.6.4                     <pip>
numpy                     1.13.1                   py27_0
openssl                   1.0.2l            vc9hb274bc6_5  [vc9]
pandas                    0.19.2                    <pip>
pandas-datareader         0.5.0                     <pip>
patsy                     0.4.1                     <pip>
pip                       9.0.1                    py27_1
pyparsing                 2.2.0                     <pip>
python                    2.7.13              h1b6d89f_16
python-dateutil           2.6.1                     <pip>
python-editor             1.0.3                     <pip>
pytz                      2017.2                    <pip>
redo                      1.6                       <pip>
requests                  2.18.4                    <pip>
requests-file             1.4.2                     <pip>
requests-ftp              0.3.1                     <pip>
s3transfer                0.1.12                    <pip>
scikit-learn              0.19.1                    <pip>
scipy                     0.19.1              np113py27_0
setuptools                36.4.0                   py27_1
six                       1.11.0                    <pip>
sortedcontainers          1.5.7                     <pip>
SQLAlchemy                1.1.14                    <pip>
sqlite                    3.13.0                    vc9_1  [vc9]
statsmodels               0.8.0                     <pip>
subprocess32              3.2.7                     <pip>
TA-Lib                    0.4.16                    <pip>
tables                    3.4.2                     <pip>
tk                        8.5.18                    vc9_0  [vc9]
toolz                     0.8.2                     <pip>
urllib3                   1.22                      <pip>
vc                        9                    h7299396_1
vs2008_runtime            9.00.30729.1         hfaea7d5_1
wheel                     0.29.0                   py27_0
wincertstore              0.2              py27hf04cefb_0
zlib                      1.2.11               hbc2faf4_2

Now that you know a little about me, let me tell you about the issue I am
having:

Description of Issue

This does not occur every time, but when I place on order on Binance live, sometimes, it does not register the order as filled. The exchange blotter continues to report the order as open, even though it clearly shows it filled on Binance. The position amount also does not update. Here is what it looks like when a buy order works:

[2018-01-22 04:18:05.033000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 3, pos_amount: 0, Minute Count: 1, Price: 1069.41, Trade Happened: False
[2018-01-22 04:18:05.546000] INFO: mean_reversion_binance: 2018-01-22 04:18:00+00:00: buying - price: 1069.41, rsi: 61.8281815443, reason: None
[2018-01-22 04:18:06.072000] INFO: CCXT: adjusted order amount 0.0922413095149 to 0.09224 based on lot size
[2018-01-22 04:18:06.619000] INFO: exchange_algorithm: statistics for the last 1 minutes:
......
[2018-01-22 04:19:00.817000] INFO: exchange_blotter: filled order 18336995 / eth_usdt: 0.09224, avg price: 1072.0
[2018-01-22 04:19:01.807000] INFO: exchange_algorithm: portfolio balances, cash: 2.3896038, positions: 98.88128

And here is what it looks like when the exchange_blotter doesn't recognize the order as filled:

[2018-01-22 04:58:04.836000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 3, pos_amount: 0, Minute Count: 1, Price: 1058.99, Trade Happened: False
[2018-01-22 04:58:05.352000] INFO: mean_reversion_binance: 2018-01-22 04:58:00+00:00: buying - price: 1058.99, rsi: 56.6059504113, reason: None
[2018-01-22 04:58:05.835000] INFO: CCXT: adjusted order amount 0.0923728494131 to 0.09237 based on lot size
[2018-01-22 04:58:06.426000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-01-22 04:59:00.707000] INFO: exchange_blotter: order 18345240 still open after 0 days 00:00:54.450000
[2018-01-22 04:59:01.196000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0
[2018-01-22 04:59:05.682000] INFO: mean_reversion_binance: Pricerise: False, Pricerisecount: 1, pos_amount: 0, Minute Count: 1, Price: 1060.79, Trade Happened: True
[2018-01-22 04:59:05.762000] INFO: exchange_algorithm: statistics for the last 1 minutes:
....
[2018-01-22 05:00:01.010000] INFO: exchange_blotter: order 18345240 still open after 0 days 00:01:54.754000
[2018-01-22 05:00:01.514000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0
[2018-01-22 05:00:06.189000] INFO: mean_reversion_binance: Pricerise: False, Pricerisecount: 2, pos_amount: 0, Minute Count: 2, Price: 1061.75, Trade Happened: True
[2018-01-22 05:00:06.271000] INFO: exchange_algorithm: statistics for the last 1 minutes:
...
[2018-01-22 05:01:00.524000] INFO: exchange_blotter: order 18345240 still open after 0 days 00:02:54.268000
[2018-01-22 05:01:01.025000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0
[2018-01-22 05:01:05.522000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 1, pos_amount: 0, Minute Count: 3, Price: 1061.56, Trade Happened: True
[2018-01-22 05:01:05.596000] INFO: exchange_algorithm: statistics for the last 1 minutes:
...
[2018-01-22 05:02:00.858000] INFO: exchange_blotter: order 18345240 still open after 0 days 00:03:54.602000
[2018-01-22 05:02:01.342000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0

Here is what I see on Binance:

binance eth trade

As you can see, the trade for $1058.99 went through successfully on the 58 minute mark. You can also see the trade on the 18 minute mark, but actually while I posted a buy at a price of $1069.41, it bought for $1072.

After reviewing that, perhaps it's related to my buy code?

orders = get_open_orders(context.market)

        if len(orders) > 0:
            log.info(
                '{} orders open, trying to cancel.'.format(
                    len(orders))
            )
            for market, position in context.portfolio.positions.iteritems():
                order_target_percent(market, 0)
        # pos_amount == 0 pricerise and
        elif pricerise and context.pricerisecount >= 3 and pos_amount == 0:
            log.info(
                '{}: buying - price: {}, rsi: {}, reason: {}'.format(
                    data.current_dt, price, getLast(indicators, 'rsi'), context.reason
                )
            )
            # Set a style for limit orders,

            order_target_percent(
                context.market, 1, limit_price=price * 1.005
            )
            context.traded_today = True
            context.tradehappened = True
        elif pricerise == False and context.pricerisecount >= 3 and pos_amount > 0:
            log.info(
                '{}: selling - price: {}, rsi: {}, reason: {}'.format(
                    data.current_dt, price, getLast(indicators, 'rsi'), context.reason
                )
            )
            #limit_price = price * 1
            order_target_percent(
                context.market, 0, limit_price=price * .995
            )
            context.traded_today = True
            context.tradehappened = True
        else:
            log.info(
                '{}: no action - price: {}, rsi: {}'.format(
                    data.current_dt, price, getLast(indicators, 'rsi')
                )
            )
            context.tradehappened = False

As you can see, I am doing limit orders for 1.005 * price for buys. The one that failed to be recognized as filled looks like it was filled immediately for the current price of the ETH, whereas the one that worked went up from the price of 1069.41 to be purchased at 1072. Perhaps it is this instant fulfillment of a limit order that's causing Catalyst to not recognize the order as being filled? If so, any recommendations? I am trading on a minute by minute basis, so I don't want to set the limit too high and have it not be filled at all, I'm trying to just purchase for basically current price.

Lastly, you can see in my order logic that I'm trying to check for any open orders and sell them off as an effort to clear out what Catalyst thinks are unfilled ones. However that line of code is never hit, so it seems like these orders which never increase my position and are considered unfilled by the exchange_blotter are in fact being removed from my "open orders" list.

Here is how you can reproduce this issue on your machine:

Reproduction Steps

  1. Hopefully the steps above are sufficient.

...

What steps have you taken to resolve this already?

Hopefully above is enough detail.
...

Anything else?

...

Sincerely,
Jarlek

@fredfortier
Copy link
Contributor

fredfortier commented Jan 22, 2018 via email

@briannewtonpsyd
Copy link
Author

I am wondering if this (at least sometimes) is related to my other reported issue (#183):

I just experience this a bit ago and here is my stack trace:

[2018-01-24 00:43:06.170000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 2, pos_amount: 0, B&H pnl: 1.03026096033, Algo pnl: 0.0, Minute Count: 1, Price: 958.0, Trade Happened: False
[2018-01-24 00:43:06.676000] INFO: mean_reversion_binance: 2018-01-24 00:43:00+00:00: no action - price: 958.0, rsi: 34.4348089043
[2018-01-24 00:43:06.717000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-01-24 00:44:00.925000] INFO: exchange_algorithm: portfolio balances, cash: 119.8649911, positions: 0.0
[2018-01-24 00:44:05.399000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 3, pos_amount: 0, B&H pnl: 1.03244871701, Algo pnl: 0.0, Minute Count: 1, Price: 955.97, Trade Happened: False
[2018-01-24 00:44:05.904000] INFO: mean_reversion_binance: 2018-01-24 00:44:00+00:00: buying - price: 955.97, rsi: 33.6957708813, reason: None
[2018-01-24 00:44:06.404000] INFO: CCXT: adjusted order amount 0.104712041885 to 0.10471 based on lot size
[2018-01-24 00:44:06.952000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-01-24 00:45:00.996000] INFO: exchange_blotter: found open order: 19178299
[2018-01-24 00:45:01.158000] INFO: exchange_blotter: order 19178299 still open after 0 days 00:00:54.248000, status: 0, amount: 1e-05
[2018-01-24 00:45:01.644000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0

My algorithm attempted to buy 100 USDT worth of ethereum and placed an order for 0.104712041885 which was adjusted to 0.10471. It then looks like even though the order was successfully placed, it then showed a remaining open order (#19178299), but the amount of that open order is 1e-05 (0.00001). Could it that even though it stated it was adjusting the order to .10471, it ordered the longer amount, thus leaving a fractional order outstanding? That's just a guess, but this behavior then sat there for the next 90 frames (1.5 hours), consistently reporting this fractional open order and not allowing any further trades since it never updated my position from 0 or lowered my cash from 100 (the beginning amount).

@fredfortier
Copy link
Contributor

This would be a logical conclusion. However, it does not appear to be this because the Catalyst order amount is set from the adjusted amount (not the original specified in the order command). Would it be possible for you to validate the "filled" amount for this particular order on Binance? We do consider the order closed only if the "remaining amount" is 0, so there must be a discrepancy between how much Binance filled versus how much we ordered. I haven't run into these myself but some conditions seem to make it more likely. We can easily solve this issue but I'd like to be sure of the root cause.

If you don't mind, use the screen bellow when validating your order history on Binance. The executed price which Catalyst uses corresponds to the "Avg" column.
screenshot 2018-01-24 00 59 40

Either way, we'll push a fix for this tomorrow. Thanks for bringing this to our attention.

@briannewtonpsyd
Copy link
Author

briannewtonpsyd commented Jan 24, 2018

Sounds good.

This is what just occurred. I tried to adjust my ordering code to only order round numbers, in case my code itself was trying to do something strange. As such, I placed an order for 1.01 and this is what happened:

[2018-01-24 06:39:04.938000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 3, pos_amount: 0, B&H pnl: 1.01041357652, Algo pnl: 5.0286, Algo Perf 4.01818642348, Time Elapsed: 2795.45599985, Minute Count: 1, Price: 987.75, Trade Happened: False
[2018-01-24 06:39:05.460000] INFO: mean_reversion_binance: 0 orders open.
[2018-01-24 06:39:05.460000] INFO: mean_reversion_binance: 2018-01-24 06:39:00+00:00: buying - price: 987.75, rsi: 58.779304817, reason: None
[2018-01-24 06:39:05.460000] INFO: CCXT: adjusted order amount 1.01 to 1.00999 based on lot size
[2018-01-24 06:39:06.005000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-01-24 06:40:00.091000] INFO: exchange_blotter: found open order: 19266859
[2018-01-24 06:40:00.247000] INFO: exchange_blotter: order 19266859 still open after 0 days 00:00:54.293000, status: 0, amount: 9.99999999984e-06

So Catalyst adjusted my 1.01 order for Eth to 1.00999, then was left with a fractional amount in as an open order.

binance order history

There's my order history, I'm attempting to do a market order for 1.01, which was converted to 1.00999, and then Binance filled a trade for 1.00998 at 988 usdt.

Hope that helps.

@fredfortier
Copy link
Contributor

fredfortier commented Jan 24, 2018 via email

@fredfortier
Copy link
Contributor

fredfortier commented Jan 25, 2018

I can see why the 1.01 => 1.00999 happens. The lot size for eth_usdt is apparently 0.000010. The CCXT amount_to_lot() method tries to avoid the order amount should be evenly divisible by lot size and converts the amount to 1.00999. This still does not explain why the order only fills 1.00998 but it could be a side-effect of placing such precise orders.

I've opened ccxt/ccxt#1483 to track this issue. I believe that the issue is simply that the lot size for ETH/USDT is too small, this causes both observed problems: 1) it unnecessarily lowers the order amount; 2) Binance trips up on such a precise order and only fills it partially which is why Catalyst never sees it as fully executed.

The issue with not being able to alter the position amount is because the Zipline performance tracker generates a portfolio dictionary on demand, instead of just passing the mutable positions objects, it creates a copy. As a results, it overrides your changes when you request it again. This isn't necessarily a bad thing, we'll address the root cause of this particular issue and come back to this as appropriate.

@briannewtonpsyd
Copy link
Author

Thanks Fred. Do you have any suggestions about how I can work around this in the meantime? I'm currently basically unable to live trade more than at max 1-2 hours at a time because eventually an order order will remain with a fractional amount, and a side effect is it seems that since it thinks an order is still open, it doesn't update the portfolio, meaning it does a buy, the buy executes, but it still shows my position as 0, so my algo tries to buy again and again until I run out of money.

Is there any way for me to manually increase the lot size or some other temporary fix?

@fredfortier
Copy link
Contributor

If you are working from source, there is a fix in the develop branch. It just disable the amount_to_lots() call for now. We'll adjust and release as soon the CCXT patch is ready (probably today). If not, I'm not sure that there is a great way to do it. We'll add an option to force your order amount in case this happens again in a future release.

@briannewtonpsyd
Copy link
Author

Hey Fred,

I pulled down the develop branch. It does appear to do a full order now, but for some reason, I'm still getting orders remaining open after a completed order, (though the previous issue of small remainders seems resolved).

[2018-01-26 06:32:05.022000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 3, pos_amount: 0, B&H pnl: 1.0041857104, Algo pnl: 0.0, Algo Perf -1.0041857104, Time Elapsed: 3780.46299982, Minute Count: 1, Price: 1069.99, Trade Happened: False
[2018-01-26 06:32:05.023000] INFO: mean_reversion_binance: 2018-01-26 06:32:00+00:00: buying - price: 1069.99, rsi: 55.0116723533, reason: None
[2018-01-26 06:32:06.078000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-01-26 06:33:00.281000] INFO: CCXT: order 19966034 executed in full: 0.93482 eth_usdt
[2018-01-26 06:33:00.281000] WARNING: CCXT: executed order amount 0.93482 differs from original
[2018-01-26 06:33:00.281000] INFO: exchange_blotter: order 19966034 still open after 0 days 00:00:54.254000
[2018-01-26 06:33:00.795000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0
[2018-01-26 06:33:05.271000] INFO: mean_reversion_binance: Pricerise: False, Pricerisecount: 1, pos_amount: 0, B&H pnl: 1.00292812028, Algo pnl: 0.0, Algo Perf -1.00292812028, Time Elapsed: 3840.71299982, Minute Count: 1, Price: 1068.65, Trade Happened: True
[2018-01-26 06:33:05.315000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-01-26 06:34:00.512000] INFO: CCXT: order 19966034 executed in full: 0.93482 eth_usdt
[2018-01-26 06:34:00.513000] INFO: exchange_blotter: order 19966034 still open after 0 days 00:01:54.486000
[2018-01-26 06:34:01.007000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0
[2018-01-26 06:34:05.506000] INFO: mean_reversion_binance: Pricerise: False, Pricerisecount: 2, pos_amount: 0, B&H pnl: 1.00370707535, Algo pnl: 0.0, Algo Perf -1.00370707535, Time Elapsed: 3900.95099998, Minute Count: 2, Price: 1069.48, Trade Happened: True
[2018-01-26 06:34:05.557000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-01-26 06:35:00.749000] INFO: CCXT: order 19966034 executed in full: 0.93482 eth_usdt
[2018-01-26 06:35:00.749000] INFO: exchange_blotter: order 19966034 still open after 0 days 00:02:54.722000
[2018-01-26 06:35:01.244000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0

binance full trade

This happened with my first order, which stopped the algo from updating the trade status, so I had to stop it from continuing.

@briannewtonpsyd
Copy link
Author

Update: I switched over to Poloniex, and am still getting this issue (even though the order is fully filled, it still thinks the order is open in Catalyst.

[2018-01-27 23:12:09.248000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 3, pos_amount: 0, B&H pnl: 1.00026745119, Algo pnl: 0.0, Algo Perf -1.00026745119, Time Elapsed: 1647.94400001, Minute Count: 1, Price: 1122.0, Trade Happened: False
[2018-01-27 23:12:09.248000] INFO: mean_reversion_binance: 2018-01-27 23:12:00+00:00: buying - price: 1122.0, rsi: 62.4274155679, reason: None
[2018-01-27 23:12:10.243000] INFO: CCXT: adjusted order amount 0.0891265597148 to 0.08912655 based on lot size
[2018-01-27 23:12:11.641000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-01-27 23:13:00.935000] INFO: CCXT: order 160536936515 executed in full: 0.08912655 eth_usdt
[2018-01-27 23:13:00.936000] INFO: exchange_blotter: order 160536936515 still open after 0 days 00:00:49.338000
[2018-01-27 23:13:01.904000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0
[2018-01-27 23:13:10.917000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 4, pos_amount: 0, B&H pnl: 0.998484443265, Algo pnl: 0.0, Algo Perf -0.998484443265, Time Elapsed: 1709.69700003, Minute Count: 1, Price: 1120.00000001, Trade Happened: True
[2018-01-27 23:13:10.959000] INFO: exchange_algorithm: statistics for the last 1 minutes:

[2018-01-27 23:14:01.551000] INFO: CCXT: order 160536936515 executed in full: 0.08912655 eth_usdt
[2018-01-27 23:14:01.552000] INFO: exchange_blotter: order 160536936515 still open after 0 days 00:01:49.955000
[2018-01-27 23:14:02.205000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0
[2018-01-27 23:14:10.631000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 5, pos_amount: 0, B&H pnl: 0.997592939289, Algo pnl: 0.0, Algo Perf -0.997592939289, Time Elapsed: 1769.56599998, Minute Count: 2, Price: 1119.0, Trade Happened: True
[2018-01-27 23:14:10.681000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-01-27 23:15:02.323000] INFO: CCXT: order 160536936515 executed in full: 0.08912655 eth_usdt
[2018-01-27 23:15:02.323000] INFO: exchange_blotter: order 160536936515 still open after 0 days 00:02:50.726000

poloniex ethusdt trade

At this point I appear to be unable to live trade ETH_USDT (At least, I will try other pairs soon) on any exchange.

@briannewtonpsyd
Copy link
Author

briannewtonpsyd commented Jan 28, 2018

Sorry to spam this thread, but just wanting to add more different scenarios. I switched to BTC_USDT on Poloniex thinking the issue might be simply with ETH.

NOTE: In order to hopefully isolate that it wasn't something with my codebase, I completely deleted my catalyst virtual environment, all the exchange/algo code in my user folder and did a full reinstall. However of course it could still be something I'm doing in my code itself.

I was able to perform one successful buy and sell:

[2018-01-28 07:28:10.379000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 3, pos_amount: 0, B&H pnl: 0.995513198655, Algo pnl: 0.0, Algo Perf -0.995513198655, Time Elapsed: 99.9790000916, Minute Count: 1, Price: 12065.6199656, Trade Happened: False
[2018-01-28 07:28:10.379000] INFO: mean_reversion_binance: 2018-01-28 07:28:00+00:00: buying - price: 12065.6199656, rsi: 70.9452909724, reason: None
[2018-01-28 07:28:11.225000] INFO: CCXT: adjusted order amount 0.0082712028155 to 0.00827119 based on lot size
[2018-01-28 07:28:12.583000] INFO: exchange_algorithm: statistics for the last 1 minutes:

[2018-01-28 07:29:02.078000] INFO: exchange_blotter: filled order 141241201537 / btc_usdt: 0.00827119, avg price: 12090.1399991
[2018-01-28 07:29:03.309000] WARNING: Exchange: detected lower balance for btc_usdt on poloniex: 0.00825052 < 0.00827119, updating position amount
[2018-01-28 07:29:03.310000] INFO: exchange_algorithm: portfolio balances, cash: 1086.89347087, positions: 99.79190735
[2018-01-28 07:29:12.329000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 4, pos_amount: 0.00825052, B&H pnl: 0.995462046376, Algo pnl: 0.0, Algo Perf -0.995462046376, Time Elapsed: 161.753000021, Minute Count: 1, Price: 12065.0, Trade Happened: True
[2018-01-28 07:29:12.391000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-01-28 07:30:01.688000] INFO: exchange_algorithm: portfolio balances, cash: 1086.89347087, positions: 99.8725446
[2018-01-28 07:30:10.532000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 5, pos_amount: 0.00825052, B&H pnl: 0.99876237641, Algo pnl: -0.457321258825, Algo Perf -1.45608363523, Time Elapsed: 220.309000015, Minute Count: 2, Price: 12105.0, Trade Happened: True
[2018-01-28 07:30:10.597000] INFO: exchange_algorithm: statistics for the last 1 minutes:

But once it tried to buy again, I got the order remaining open again:

[2018-01-28 08:40:00.534000] INFO: exchange_algorithm: portfolio balances, cash: 1185.85780577, positions: 0.0

[2018-01-28 08:40:09.293000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 10, pos_amount: 0, B&H pnl: 0.985954936834, Algo pnl: -0.787479241871, Algo Perf -1.77343417871, Time Elapsed: 4418.88499999, Minute Count: 15, Price: 11949.7738324, Trade Happened: True
[2018-01-28 08:40:09.293000] INFO: mean_reversion_binance: 2018-01-28 08:40:00+00:00: buying - price: 11949.7738324, rsi: 59.8913939093, reason: None
[2018-01-28 08:40:10.348000] INFO: CCXT: adjusted order amount 0.00830246012601 to 0.00830245 based on lot size
[2018-01-28 08:40:11.718000] INFO: exchange_algorithm: statistics for the last 1 minutes:                                                                                                                   

[2018-01-28 08:41:01.055000] INFO: exchange_blotter: order 141257295427 still open after 0 days 00:00:50.055000
[2018-01-28 08:41:02.335000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0
[2018-01-28 08:41:11.032000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 11, pos_amount: 0, B&H pnl: 0.987766670302, Algo pnl: -0.787479241871, Algo Perf -1.77524591217, Time Elapsed: 4480.61899996, Minute Count: 1, Price: 11971.732042, Trade Happened: True
[2018-01-28 08:41:11.080000] INFO: exchange_algorithm: statistics for the last 1 minutes:
                                                                                                        
[2018-01-28 08:42:00.459000] INFO: exchange_blotter: order 141257295427 still open after 0 days 00:01:49.459000
[2018-01-28 08:42:01.663000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0

[2018-01-28 08:42:10.411000] INFO: mean_reversion_binance: Pricerise: True, Pricerisecount: 12, pos_amount: 0, B&H pnl: 0.987766670303, Algo pnl: -0.787479241871, Algo Perf -1.77524591217, Time Elapsed: 4540.01400018, Minute Count: 2, Price: 11971.732042, Trade Happened: True
[2018-01-28 08:42:10.457000] INFO: exchange_algorithm: statistics for the last 1 minutes:
                                                                                                              
[2018-01-28 08:43:01.596000] INFO: exchange_blotter: order 141257295427 still open after 0 days 00:02:50.596000
[2018-01-28 08:43:02.274000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0

poloniex btc trade

What I noticed is that for the first successful buy, Catalyst actually realized the balance on Poloniex was different than what was ordered (.00825052 rather than the expected .00827119) and updated the position amount accordingly. For the second buy, it thought it was buying .00830245, but actually Poloniex filled .00830244 (perhaps due to the commission cost?), and it looks like Catalyst then perpetually felt the order was still open.

Fred, I'm sorry if this is all the same issue that you're waiting on a patch from CCXT, but since these orders are being filled without Catalyst retaining a small fraction (and it's not just ETH_USDT on Binance), I thought it might be a different issue.

If it helps, here is my buy code:

current = data.current(context.market, fields=['close', 'volume'])
price = current['close']

order_target_percent(
                context.market, 1, limit_price=price * 1.005
            )

Thanks,

Brian

@briannewtonpsyd briannewtonpsyd changed the title Completed orders on Binance (at least) are sometimes being reported as perpetually "not filled" by exchange_blotter Completed orders on Binance & Poloniex are sometimes being reported as perpetually "not filled" by exchange_blotter Jan 28, 2018
@fredfortier
Copy link
Contributor

fredfortier commented Jan 29, 2018 via email

@fredfortier
Copy link
Contributor

fredfortier commented Jan 30, 2018

Implemented a workaround as suggested by the CCXT developers: ccxt/ccxt#1483. We'll implement a more permanent solution when available.

@Ericxgao
Copy link

@fredfortier

I tried installing catalyst on the develop branch and ran into this:

[2018-01-30 08:17:04.690587] INFO: gas_btc: 2018-01-30 08:17:00+00:00: buying - price: 0.005829
[2018-01-30 08:17:04.690692] INFO: gas_btc: 0.00605038095238: limit - stop: 0.00568680952381
[2018-01-30 08:17:05.753630] INFO: exchange_algorithm: statistics for the last 1 minutes:
                           starting_cash  ending_cash  portfolio_value  pnl  long_exposure  short_exposure  orders  transactions
period_close                                                                                                                    
2018-01-30 08:18:00+00:00           0.05         0.05             0.05  0.0              0               0       0             0
[2018-01-30 08:18:00.934541] INFO: CCXT: order 6943670 executed in full: 8.57 gas_btc
[2018-01-30 08:18:00.934873] WARNING: CCXT: executed order amount 8.57 differs from original
[2018-01-30 08:18:00.935034] INFO: exchange_blotter: partial order 6943670 / gas_btc: 0, avg price: 0.0
Traceback (most recent call last):
  File "binance_catalyst_live.py", line 248, in <module>
    simulate_orders=False
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/run_algo.py", line 551, in run_algorithm
    stats_output=stats_output
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/run_algo.py", line 330, in _run
    overwrite_sim_params=False,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 297, in run
    data, overwrite_sim_params
  File "/usr/local/lib/python2.7/dist-packages/catalyst/algorithm.py", line 724, in run
    for perf in self.get_generator():
  File "/usr/local/lib/python2.7/dist-packages/catalyst/gens/tradesimulation.py", line 224, in transform
    for capital_change_packet in every_bar(dt):
  File "/usr/local/lib/python2.7/dist-packages/catalyst/gens/tradesimulation.py", line 137, in every_bar
    handle_data(algo, current_data, dt_to_use)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/events.py", line 216, in handle_data
    dt,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/events.py", line 235, in handle_data
    self.callback(context, data)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 741, in handle_data
    cleanup=lambda: log.warn('Ordering again.')
  File "/usr/local/lib/python2.7/dist-packages/redo/__init__.py", line 162, in retry
    return action(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 606, in synchronize_portfolio
    cash=required_cash,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange.py", line 707, in sync_positions
    tickers = self.tickers(assets)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/ccxt/ccxt_exchange.py", line 1001, in tickers
    symbol = self.get_symbol(assets[0])
TypeError: 'set' object does not support indexing

@fredfortier
Copy link
Contributor

fredfortier commented Jan 30, 2018 via email

@Ericxgao
Copy link

Running on binance live, no simulated orders. Thanks!

@briannewtonpsyd
Copy link
Author

briannewtonpsyd commented Jan 30, 2018 via email

@Ericxgao
Copy link

@brinew27 Which commits were those? I tried making a custom installation with those edits but I'm still getting the same errors.

@briannewtonpsyd
Copy link
Author

briannewtonpsyd commented Jan 31, 2018

@Ericxgao They are labeled with the bug number. The commits are "f34a66e" and "5c236a6". Uninstall your develop Catalyst, reinstall with the master branch, then just do those two commits manually. I'm seeing if the position not updating is related to the latest version of CCXT (about to rollback to 1.10.774).

Edit: After rolling back to 1.10.774 CCXT it seems to be tracking position fine. I did make a small change to my code to only perform a buy when my pos_amount is under say .0001 so it wouldn't continue to perform buys if there was a fractional amount of eth left. I think I'm finally at a point to trade live continually with Fred's two workaround lines of code! Thanks Fred!

@briannewtonpsyd
Copy link
Author

briannewtonpsyd commented Jan 31, 2018

I take it back. While Binance orders seem to executing fine (when I do a market order), Limit buy orders on Poloniex for the current price still are reported as continually open in Catalyst, despite being fully filled on Poloniex.

Edit: Very weird, now Binance is also showing open orders again, I didn't change any of the catalyst code, this is very strange.

@fredfortier
Copy link
Contributor

fredfortier commented Jan 31, 2018 via email

@Ericxgao
Copy link

Ericxgao commented Jan 31, 2018 via email

@fredfortier
Copy link
Contributor

Okay. I'll try with the same parameters.

@fredfortier
Copy link
Contributor

I using CCXT 1.10.944. We can downgrade if necessary but I'd want to clearly isolate the root cause first. I'd rather keep up with the latest release whenever possible. I'll post an update after making a few transaction with elf_btc on Binance.

@Ericxgao
Copy link

Ericxgao commented Feb 1, 2018 via email

@fredfortier
Copy link
Contributor

Okay, let me make sure that everything is working with 1.10.944 and I'll get back to you.

@fredfortier
Copy link
Contributor

fredfortier commented Feb 1, 2018

Here is why we tripped up and why downgrading CCXT made a difference for you guys: ccxt/ccxt#1680. I made the related adjustments and re-testing. The orders were being processed by the fallback method (see comment about Poloniex above). There's a second issue which I commented on here: ccxt/ccxt#1483. I'm finalizing a workaround for this as well.

@fredfortier
Copy link
Contributor

I believe that we have this resolved finally. I accounted for the two issues referenced above and tested with a variety of order types and markets. I'll run more transactions before pushing a release.

@fredfortier
Copy link
Contributor

Here is what a clean log looks like on my side:

[2018-02-01 04:37:43.271458] INFO: mean_reversion_risk: 2018-02-01 04:37:00+00:00: buying - price: 0.00540021, rsi: 31.724827115
[2018-02-01 04:37:44.293394] INFO: CCXT: order amount adjusted by binance from 37.03559676 to 37.0

Then in the next frame:

[2018-02-01 04:38:00.258216] INFO: exchange_blotter: filled order 7641440 / ven_eth: 37.0, avg price: 0.00540184189189

I processed multiple transactions but I'll let it run overnight before releasing just to be sure that the sample is sufficient.

@briannewtonpsyd
Copy link
Author

@fredfortier Thanks so much for your focus on this Fred, I really appreciate it! I'm running the develop branch and .994 version of CCXT and crosses fingers so far so good.

Sample from Binance (ETH_USDT), using order target percent, market order:

[2018-02-01 03:57:00.442000] INFO: exchange_algorithm: portfolio balances, cash: 1721.04399002, positions: 0.0
[2018-02-01 03:57:05.454000] INFO: mean_reversion_binance: 2018-02-01 03:57:00+00:00: buying - price: 1141.0, rsi: 57.0534267441, reason: None
[2018-02-01 03:57:06.454000] INFO: CCXT: order amount adjusted by binance from 0.08771699 to 0.08771

Next Frame

[2018-02-01 03:58:00.883000] INFO: exchange_blotter: filled order 22336928 / eth_usdt: 0.08771, avg price: 1140.98
[2018-02-01 03:58:01.719000] INFO: exchange_algorithm: portfolio balances, cash: 1420.90304962, positions: 100.0543054

Sample from Poloniex (XRP_USDT), using order target percent, limit order:

[2018-02-01 03:44:01.135000] INFO: exchange_algorithm: portfolio balances, cash: 1078.24499824, positions: 0.0
[2018-02-01 03:44:10.060000] INFO: mean_reversion_poloniex: Pricerise: True, Pricerisecount: 6, pos_amount: 0, B&H pnl: -1.22242869893, Algo pnl: 0.0, Algo Perf 1.22242869893, Time Elapsed: 28.923149999, Minute Count: 1, Price: 1.10795386, Trade Happened: False
[2018-02-01 03:44:11.289000] INFO: mean_reversion_poloniex: 2018-02-01 03:44:00+00:00: buying - price: 1.10795386, rsi: 42.4014562547, reason: None

Next Frame

[2018-02-01 03:45:00.734000] INFO: exchange_blotter: filled order 80263697086 / xrp_usdt: 90.2564661, avg price: 1.10795386
[2018-02-01 03:45:02.874000] INFO: exchange_algorithm: portfolio balances, cash: 978.24499824, positions: 99.9000093795

Only thing that was slightly odd out of that, is after the Poloniex order was filled, Catalyst listed my "Ending Cash" as "-5.45415446e-09", from an original 100. I'm assuming that was due to the adjustment in precision down from what would normally be a 100% order. Didn't seem to have any lasting negative effect, but just was a bit odd.

I'll also let these run through the night, and if we're clear I'll let you know as well. Thanks again for your help!

@briannewtonpsyd
Copy link
Author

@fredfortier My code worked successfully for much of the night, but did encounter an error:

It had a position, then tried to sell ETH_USDT on Binance:

[2018-02-01 14:06:01.598000] INFO: exchange_algorithm: portfolio balances, cash: 1624.53974482, positions: 98.8011871
[2018-02-01 14:06:06.099000] INFO: mean_reversion_binance: Pricerise: False, Pricerisecount: 6, pos_amount: 0.08629, B&H pnl: -1.07438516968, Algo pnl: -1.1581606, Algo Perf -0.0837754303215, Time Elapsed: 651.143099999, Minute Count: 1, Price: 1143.59, Trade Happened: False
[2018-02-01 14:06:06.614000] INFO: mean_reversion_binance: 2018-02-01 14:06:00+00:00: selling - price: 1143.59, rsi: 56.6805615511, reason: None
[2018-02-01 14:07:00.177000] INFO: exchange_blotter: order 22570155 still open after 0 days 00:00:52.570000
[2018-02-01 14:07:01.147000] WARNING: Exchange: detected lower balance for eth_usdt on binance: 4.42e-06 < 0.08629, updating position amount
[2018-02-01 14:07:01.148000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 98.7658082
[2018-02-01 14:07:05.662000] INFO: mean_reversion_binance: Pricerise: False, Pricerisecount: 7, pos_amount: 4.42e-06, B&H pnl: -0.951548862034, Algo pnl: -1.1944024, Algo Perf -0.242853537966, Time Elapsed: 652.135616668, Minute Count: 1, Price: 1145.01, Trade Happened: True
[2018-02-01 14:08:00.218000] INFO: exchange_blotter: order 22570155 still open after 0 days 00:01:52.611000
[2018-02-01 14:08:01.191000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0050640824
[2018-02-01 14:08:05.692000] INFO: mean_reversion_binance: Pricerise: False, Pricerisecount: 8, pos_amount: 4.42e-06, B&H pnl: -0.952413906454, Algo pnl: -99.9905304564, Algo Perf -99.0381165499, Time Elapsed: 653.136333334, Minute Count: 2, Price: 1145.0, Trade Happened: True
[2018-02-01 14:09:00.221000] INFO: exchange_blotter: order 22570155 still open after 0 days 00:02:52.614000
[2018-02-01 14:09:01.187000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0050388

If I can tell what happened, it looks like it sold again for not the entire amount and left a fractional value, and considered the order still open. Here is what occurred on Binance:

binance orders

Catalyst had my position at .08629, did sell that amount, but saw a lower amount on Binance and adjusted my position to that small amount. My current ETH balance on Binance is "ETH Balance: 0.00000442". I believe that balance has been sitting there for some time, prior to running this algo, so I'm wondering if it detected a remaining balance for ETH and adjusted my position to that, even though that wasn't part of the original purchase.

@fredfortier
Copy link
Contributor

fredfortier commented Feb 1, 2018 via email

@Ericxgao
Copy link

Ericxgao commented Feb 2, 2018

I'm running into issues now as well - not sure if related. For some reason it thinks these response objects are lists, not dicts.

I haven't logged these exceptions, but I've had some issues similar to this when doing some exchange API stuff before - I'm running this script threaded on over 40 coins, so it could be possible that I'm getting rate limited. But I know Binance has a pretty high rate limit, so this might be completely off.

Exception in thread iota_btc:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "binance_catalyst_live.py", line 240, in run
    simulate_orders=False
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/run_algo.py", line 551, in run_algorithm
    stats_output=stats_output
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/run_algo.py", line 330, in _run
    overwrite_sim_params=False,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 297, in run
    data, overwrite_sim_params
  File "/usr/local/lib/python2.7/dist-packages/catalyst/algorithm.py", line 724, in run
    for perf in self.get_generator():
  File "/usr/local/lib/python2.7/dist-packages/catalyst/gens/tradesimulation.py", line 224, in transform
    for capital_change_packet in every_bar(dt):
  File "/usr/local/lib/python2.7/dist-packages/catalyst/gens/tradesimulation.py", line 137, in every_bar
    handle_data(algo, current_data, dt_to_use)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/events.py", line 216, in handle_data
    dt,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/events.py", line 235, in handle_data
    self.callback(context, data)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 741, in handle_data
    cleanup=lambda: log.warn('Ordering again.')
  File "/usr/local/lib/python2.7/dist-packages/redo/__init__.py", line 162, in retry
    return action(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 606, in synchronize_portfolio
    cash=required_cash,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange.py", line 684, in sync_positions
    balances = self.get_balances()
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/ccxt/ccxt_exchange.py", line 630, in get_balances
    balances = self.api.fetch_balance()
  File "/usr/local/lib/python2.7/dist-packages/ccxt/binance.py", line 423, in fetch_balance
    balances = response['balances']
TypeError: list indices must be integers, not str

Exception in thread nuls_btc:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "binance_catalyst_live.py", line 240, in run
    simulate_orders=False
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/run_algo.py", line 551, in run_algorithm
    stats_output=stats_output
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/run_algo.py", line 330, in _run
    overwrite_sim_params=False,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 297, in run
    data, overwrite_sim_params
  File "/usr/local/lib/python2.7/dist-packages/catalyst/algorithm.py", line 724, in run
    for perf in self.get_generator():
  File "/usr/local/lib/python2.7/dist-packages/catalyst/gens/tradesimulation.py", line 224, in transform
    for capital_change_packet in every_bar(dt):
  File "/usr/local/lib/python2.7/dist-packages/catalyst/gens/tradesimulation.py", line 137, in every_bar
    handle_data(algo, current_data, dt_to_use)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/events.py", line 216, in handle_data
    dt,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/events.py", line 235, in handle_data
    self.callback(context, data)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 741, in handle_data
    cleanup=lambda: log.warn('Ordering again.')
  File "/usr/local/lib/python2.7/dist-packages/redo/__init__.py", line 162, in retry
    return action(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 606, in synchronize_portfolio
    cash=required_cash,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange.py", line 707, in sync_positions
    tickers = self.tickers(assets)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/ccxt/ccxt_exchange.py", line 1017, in tickers
    results[symbol] = self.api.fetch_ticker(symbol=symbol)
  File "/usr/local/lib/python2.7/dist-packages/ccxt/binance.py", line 485, in fetch_ticker
    return self.parse_ticker(response, market)
  File "/usr/local/lib/python2.7/dist-packages/ccxt/binance.py", line 450, in parse_ticker
    symbol = ticker['symbol']
TypeError: list indices must be integers, not str


Exception in thread trx_btc:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "binance_catalyst_live.py", line 240, in run
    simulate_orders=False
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/run_algo.py", line 551, in run_algorithm
    stats_output=stats_output
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/run_algo.py", line 330, in _run
    overwrite_sim_params=False,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 297, in run
    data, overwrite_sim_params
  File "/usr/local/lib/python2.7/dist-packages/catalyst/algorithm.py", line 724, in run
    for perf in self.get_generator():
  File "/usr/local/lib/python2.7/dist-packages/catalyst/gens/tradesimulation.py", line 224, in transform
    for capital_change_packet in every_bar(dt):
  File "/usr/local/lib/python2.7/dist-packages/catalyst/gens/tradesimulation.py", line 137, in every_bar
    handle_data(algo, current_data, dt_to_use)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/events.py", line 216, in handle_data
    dt,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/utils/events.py", line 235, in handle_data
    self.callback(context, data)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 741, in handle_data
    cleanup=lambda: log.warn('Ordering again.')
  File "/usr/local/lib/python2.7/dist-packages/redo/__init__.py", line 162, in retry
    return action(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange_algorithm.py", line 606, in synchronize_portfolio
    cash=required_cash,
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/exchange.py", line 684, in sync_positions
    balances = self.get_balances()
  File "/usr/local/lib/python2.7/dist-packages/catalyst/exchange/ccxt/ccxt_exchange.py", line 630, in get_balances
    balances = self.api.fetch_balance()
  File "/usr/local/lib/python2.7/dist-packages/ccxt/binance.py", line 423, in fetch_balance
    balances = response['balances']
KeyError: 'balances'

@fredfortier
Copy link
Contributor

Thanks. I will look into this shortly.

@fredfortier
Copy link
Contributor

@Ericxgao It's hard to tell what's going on with that last issue. We'll create a unit test which includes 40 markets to better investigate. In the meantime, you could try upgrading to Python 3 to see if it makes a difference.

@brinew27 I'm investigating this.

My current ETH balance on Binance is "ETH Balance: 0.00000442". I believe that balance has been sitting there for some time, prior to running this algo, so I'm wondering if it detected a remaining balance for ETH and adjusted my position to that, even though that wasn't part of the original purchase.

@fredfortier
Copy link
Contributor

See notes in issue #183, I believe that the problem with some orders staying open when filled is finally resolved.

I'm still looking into the separate issues in this thread.

@briannewtonpsyd
Copy link
Author

Hey @fredfortier,

Unfortunately, I still ran into an issue with an order staying open last night after about a day of running. It seems to have occurred after selling off my position, the blotter didn't recognize my order as being filled, but it did detect that my balance on Poloniex was less than it registered, so reduced my amount. It then tried to buy again, but my cash etc hadn't been updated since the order wasn't seen as filled, so it crashed (or so I believe). You can see this at 5:42, the blotter detects the order as still open, but adjusts my position because my eth has been reduced to 0.

[2018-02-10 05:37:01.393000] INFO: exchange_algorithm: portfolio balances, cash: 1113.90019447, positions: 96.58594452
[2018-02-10 05:37:12.680000] INFO: mean_reversion_poloniex_eth_usdt: Pricerise: False, Pricerisecount: 2, pos_amount: 0.1079052, B&H pnl: 8.47464456202, Algo pnl: -3.4681438022, Algo Perf -11.9427883642, Time Elapsed: 1198.86781667, Minute Count: 1, Price: 894.94836003, Trade Happened: False
[2018-02-10 05:37:13.713000] INFO: mean_reversion_poloniex_eth_usdt: 2018-02-10 05:37:00+00:00: no action - price: 894.94836003, rsi: 60.5456059253
[2018-02-10 05:37:13.830000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-02-10 05:38:02.138000] INFO: exchange_algorithm: portfolio balances, cash: 1113.90019447, positions: 96.3070095543
[2018-02-10 05:38:11.122000] INFO: mean_reversion_poloniex_eth_usdt: Pricerise: False, Pricerisecount: 3, pos_amount: 0.1079052, B&H pnl: 8.1797025296, Algo pnl: -3.4681438022, Algo Perf -11.6478463318, Time Elapsed: 1199.83108333, Minute Count: 1, Price: 892.51499978, Trade Happened: False
[2018-02-10 05:38:12.690000] INFO: mean_reversion_poloniex_eth_usdt: 2018-02-10 05:38:00+00:00: no action - price: 892.51499978, rsi: 59.4282270047
[2018-02-10 05:38:12.799000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-02-10 05:39:03.489000] INFO: exchange_algorithm: portfolio balances, cash: 1113.90019447, positions: 96.3070095543
[2018-02-10 05:39:12.384000] INFO: mean_reversion_poloniex_eth_usdt: Pricerise: False, Pricerisecount: 4, pos_amount: 0.1079052, B&H pnl: 8.1797025296, Algo pnl: -3.74707876794, Algo Perf -11.9267812975, Time Elapsed: 1200.85245, Minute Count: 1, Price: 892.51499978, Trade Happened: False
[2018-02-10 05:39:13.509000] INFO: mean_reversion_poloniex_eth_usdt: 2018-02-10 05:39:00+00:00: no action - price: 892.51499978, rsi: 57.7392705068
[2018-02-10 05:39:13.641000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-02-10 05:40:02.012000] INFO: exchange_algorithm: portfolio balances, cash: 1113.90019447, positions: 96.307549104
[2018-02-10 05:40:11.005000] INFO: mean_reversion_poloniex_eth_usdt: Pricerise: False, Pricerisecount: 5, pos_amount: 0.1079052, B&H pnl: 8.18030859484, Algo pnl: -3.74707876794, Algo Perf -11.9273873628, Time Elapsed: 1201.82811667, Minute Count: 1, Price: 892.52, Trade Happened: False
[2018-02-10 05:40:13.508000] INFO: mean_reversion_poloniex_eth_usdt: 2018-02-10 05:40:00+00:00: no action - price: 892.52, rsi: 57.7444477159
[2018-02-10 05:40:13.621000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-02-10 05:41:01.889000] INFO: exchange_algorithm: portfolio balances, cash: 1113.90019447, positions: 96.1303903337
[2018-02-10 05:41:10.947000] INFO: mean_reversion_poloniex_eth_usdt: Pricerise: False, Pricerisecount: 6, pos_amount: 0.1079052, B&H pnl: 7.98130975601, Algo pnl: -3.7465392182, Algo Perf -11.7278489742, Time Elapsed: 1202.82843333, Minute Count: 1, Price: 890.87819988, Trade Happened: False
[2018-02-10 05:41:13.367000] INFO: mean_reversion_poloniex_eth_usdt: 2018-02-10 05:41:00+00:00: selling - price: 890.87819988, rsi: 56.0930021245, reason: None
[2018-02-10 05:41:14.943000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-02-10 05:42:00.340000] INFO: exchange_blotter: order 163949802233 still open after 0 days 00:00:49.340000
[2018-02-10 05:42:02.220000] WARNING: Exchange: detected lower balance for eth_usdt on poloniex: 0.0 < 0.1079052, updating position amount
[2018-02-10 05:42:02.220000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 96.3429635151
[2018-02-10 05:42:11.324000] INFO: mean_reversion_poloniex_eth_usdt: Pricerise: False, Pricerisecount: 7, pos_amount: 0, B&H pnl: 7.98130975601, Algo pnl: -3.92369798851, Algo Perf -11.9050077445, Time Elapsed: 1203.83281666, Minute Count: 1, Price: 890.87819988, Trade Happened: True
[2018-02-10 05:42:11.414000] INFO: exchange_algorithm: statistics for the last 1 minutes:
[2018-02-10 05:43:01.454000] INFO: exchange_blotter: order 163949802233 still open after 0 days 00:01:50.454000
[2018-02-10 06:08:01.004000] INFO: exchange_blotter: order 163949802233 still open after 0 days 00:26:50.003000
[2018-02-10 06:08:03.817000] INFO: exchange_algorithm: portfolio balances, cash: 0.0, positions: 0.0
[2018-02-10 06:08:11.951000] INFO: mean_reversion_poloniex_eth_usdt: Pricerise: True, Pricerisecount: 6, pos_amount: 0, B&H pnl: 8.06857943348, Algo pnl: -100.054088322, Algo Perf -108.122667756, Time Elapsed: 1229.84526666, Minute Count: 1, Price: 891.5982009, Trade Happened: False
[2018-02-10 06:08:13.050000] INFO: mean_reversion_poloniex_eth_usdt: 2018-02-10 06:08:00+00:00: buying - price: 891.5982009, rsi: 55.7018258267, reason: None
[2018-02-10 06:08:15.038000] WARNING: CCXT: the exchange rejected the order: poloniex {"error":"Total must be at least 1."}
Traceback (most recent call last):
  File "Z:/Users/Brian/Google Drive/Catalyst/mean_reversion_simple - Poloniex.py", line 636, in <module>
    stats_output=None,
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\utils\run_algo.py", line 551, in run_algorithm
    stats_output=stats_output
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\utils\run_algo.py", line 330, in _run
    overwrite_sim_params=False,
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\exchange\exchange_algorithm.py", line 309, in run
    data, overwrite_sim_params
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\algorithm.py", line 724, in run
    for perf in self.get_generator():
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\gens\tradesimulation.py", line 224, in transform
    for capital_change_packet in every_bar(dt):
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\gens\tradesimulation.py", line 137, in every_bar
    handle_data(algo, current_data, dt_to_use)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\utils\events.py", line 216, in handle_data
    dt,
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\utils\events.py", line 235, in handle_data
    self.callback(context, data)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\exchange\exchange_algorithm.py", line 761, in handle_data
    self._handle_data(self, data)
  File "Z:/Users/Brian/Google Drive/Catalyst/mean_reversion_simple - Poloniex.py", line 262, in handle_data
    context.market, 1, limit_price=price * 1.005
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\utils\api_support.py", line 57, in wrapped
    return getattr(algo_instance, f.__name__)(*args, **kwargs)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\utils\api_support.py", line 126, in wrapped_method
    return method(self, *args, **kwargs)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\algorithm.py", line 2055, in order_target_percent
    style=style)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\utils\api_support.py", line 126, in wrapped_method
    return method(self, *args, **kwargs)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\algorithm.py", line 1462, in order
    return self.blotter.order(asset, amount, style)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\exchange\exchange_blotter.py", line 169, in order
    if amount == 0:
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\exchange\exchange_blotter.py", line 185, in order
    args=(asset, amount, style),
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\redo\__init__.py", line 162, in retry
    return action(*args, **kwargs)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\exchange\exchange_blotter.py", line 163, in exchange_order
    asset, amount, style
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\exchange\exchange.py", line 823, in order
    return self.create_order(asset, amount, is_buy, style)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\exchange\ccxt\ccxt_exchange.py", line 791, in create_order
    raise CreateOrderError(exchange=self.name, error=e)
catalyst.exchange.exchange_errors.CreateOrderError: Unable to create order on exchange poloniex poloniex {"error":"Total must be at least 1."}.
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\atexit.py", line 24, in _run_exitfuncs
    func(*targs, **kargs)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\__init__.py", line 67, in cleanup_tempdir
    shutil.rmtree(tempdir)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\shutil.py", line 239, in rmtree
    onerror(os.listdir, path, sys.exc_info())
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\shutil.py", line 237, in rmtree
    names = os.listdir(path)
WindowsError: [Error 3] The system cannot find the path specified: 'c:\\users\\brian\\appdata\\local\\temp\\tmpr_p0fk/*.*'
Error in sys.exitfunc:
Traceback (most recent call last):
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\atexit.py", line 24, in _run_exitfuncs
    func(*targs, **kargs)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\site-packages\catalyst\__init__.py", line 67, in cleanup_tempdir
    shutil.rmtree(tempdir)
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\shutil.py", line 239, in rmtree
    onerror(os.listdir, path, sys.exc_info())
  File "C:\Users\brian\Anaconda2\envs\catalyst\lib\shutil.py", line 237, in rmtree
    names = os.listdir(path)
WindowsError: [Error 3] The system cannot find the path specified: 'c:\\users\\brian\\appdata\\local\\temp\\tmpr_p0fk/*.*'

Process finished with exit code 1

@fredfortier
Copy link
Contributor

Okay thank you for the precision. I understand what happened now with Poloniex adjusting the order amount. We'll take care of this ASAP, tentatively this weekend and if not on Monday,

@SOGorman35
Copy link

SOGorman35 commented Feb 21, 2018

any update on this? I'm trying a workaround, but have only traded once or twice since implementing it, so it is too soon to say if it works for sure. My best attempt at preventing orders from getting "stuck" was to change from order_target_percent or order_target_value to the following:

limit_price = price * context.limit_buy_pct
buy_amount = (cash/limit_price) * context.target_buy_pct
order_target(context.market, round(buy_amount, 8), limit_price=limit_price)

This is on Poloniex, FYI. If I was using Binance, I'd probably change the rounding to 6 or 3 or 0 or whatever the fractional amount that Binance allows for that specific coin.

I will note too that when I live traded on Robinhood using Quantopian last year, I frequently had blotter errors throwing everything off. Usually it was incorrect position reporting, which led to the strategy placing the order for a second time or failing to exit a position.

@fredfortier
Copy link
Contributor

fredfortier commented Feb 22, 2018 via email

@AvishaiW
Copy link
Contributor

added to catalyst 0.5.4, feel free to reopen if errors still occur

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants