Wrong trade profit calculation

[laloch]

System information

• Have I written custom code (as opposed to using zenbot vanilla): yes, completely unrelated
• OS Platform and Distribution (e.g., Linux Ubuntu 16.04): Archlinux
• Zenbot version: Git master branch @f235ba1e39
• NodeJS version: v9.4.0
• Python version: 2.7.14
• Exact command to reproduce: ./zenbot.sh trade --strategy=forex_analytics --period=3m --modelfile models/iot3m.json bitfinex.IOT-USD

Describe the problem

As can be seen in the below live trading log, the profit calculated since the last trade diverts from the actual price movement. In this case from +0.89% to -1.72% despite the price growing by 0.51%.

Source code / logs

2018-01-19 16:09:00  2.75440 IOT-USD   +0.39%    40848    -- 39     +2.68%    2.53003983 IOT  715.74 USD   -9.78%   +0.78%
2018-01-19 16:12:00  2.74540 IOT-USD   -0.33%    34730    -- 37     buying    2.53003983 IOT  715.74 USD   -9.79%   +1.11%
2018-01-19 16:12:02  2.75990 IOT-USD   +0.52%      400    -- 42     buying    2.53003983 IOT  715.74 USD   -9.78%   +0.58%
buy order completed at 2018-01-19 16:12:06:

257.51751024 IOT at 2.74540 USD
total 706.988 USD
-0.0255% slippage (orig. price 2.74610 USD)
execution: a few seconds

2018-01-19 16:15:00  2.74860 IOT-USD   +0.11%    14477    -- 38     bought  259.53251505 IOT    5.20 USD  -10.30%   +0.41%
2018-01-19 16:18:00  2.77000 IOT-USD   +0.77%    23705    -- 45     +0.89%  259.53251505 IOT    5.20 USD   -9.61%   +0.40%
2018-01-19 16:21:00  2.78420 IOT-USD   +0.51%    28447     - 49     -1.72%  259.53251505 IOT    5.20 USD   -9.15%   +0.40%
2018-01-19 16:24:00  2.79120 IOT-USD   +0.25%    42616   51 +       -1.47%  259.53251505 IOT    5.20 USD   -8.92%   +0.40%

[laloch]

It's worth noting that just an hour later the sell_stop_pct stop didn't trigger. I have the engine patched in such a way that the sell_stop triggers only if the last trade was 'buy': if (do_sell_stop && !s.buy_order && s.sell_stop && last_trade.type === 'buy' && s.period.close < s.sell_stop). So my guess is that the engine "forgot" about the last trade somewhere between 16:18 and 16:21.

[laloch]

I can now confirm the above speculation about the last trade being "forgotten". I have added the last trade value price and trade count to the console output:

@@ -762,6 +762,13 @@ module.exports = function container (get, set, clear) {
       else {
         process.stdout.write(z(9, '', ' '))
       }
+      var last_trade = s.my_trades[s.my_trades.length - 1]
+      if (last_trade) {
+        process.stdout.write(z(8, last_trade.price, ' ')[last_trade.type === 'buy' ? 'green' : 'red'])
+      } else {
+        process.stdout.write(z(8, '', ' '))
+      }
+      process.stdout.write(z(3, s.my_trades.length, ' '))
       var orig_capital = s.orig_capital || s.start_capital
       var orig_price = s.orig_price || s.start_price
       if (orig_capital) {

These are the results:

2018-01-30 05:36:00  2.48260 IOT-USD   +0.51%    29530   57 ++      buying          0  2.28999180 IOT  588.98 USD  -25.77%   -8.00%
2018-01-30 05:36:26  2.47580 IOT-USD   -0.28%       30   53 +       buying          0  2.28999180 IOT  588.98 USD  -25.77%   -7.75%
buy order completed at 2018-01-30 05:36:40:

235.04498878 IOT at 2.48260 USD
[...]
2018-01-30 05:42:00  2.47530 IOT-USD   -0.04%     3630   52 +         sell   2.4826  1  236.86489060 IOT    5.45 USD  -26.13%   -8.18%
2018-01-30 05:43:23  2.47530 IOT-USD   +0.00%     1849   52 +      selling   2.4826  1  236.86489060 IOT    5.45 USD  -26.13%   -8.18%
sell order completed at 2018-01-30 05:43:27:

234.49624169 IOT at 2.47530 USD
[...]
2018-01-30 05:45:00  2.48140 IOT-USD   +0.24%    24548   56 ++        sold   2.4753  2    2.36864891 IOT  584.74 USD  -26.27%   -8.58%
2018-01-30 05:48:00  2.47600 IOT-USD   -0.22%    26728   52 +         sell   2.4753  2    2.36864891 IOT  584.74 USD  -26.28%   -8.38%
[...]
2018-01-30 08:42:00  2.41480 IOT-USD   +0.00%    28939     - 49        buy   2.4753  2    2.36864891 IOT  584.74 USD  -26.29%   -6.08%
2018-01-30 08:42:01  2.41400 IOT-USD   -0.04%      863     - 48     buying   2.4753  2    2.36864891 IOT  584.74 USD  -26.29%   -6.05%
buy order completed at 2018-01-30 08:42:06:

239.32894773 IOT at 2.41480 USD
[...]
2018-01-30 09:54:00  2.48930 IOT-USD   +0.01%     4452   63 ++      +3.08%   2.4148  3  241.21893874 IOT    7.00 USD  -24.17%   -6.27%
2018-01-30 09:57:00  2.48490 IOT-USD   -0.18%    10500   59 ++     selling   2.4826  3  241.21893874 IOT    7.00 USD  -24.30%   -6.27%
                                                                             ^^^^^^
2018-01-30 09:57:03  2.48400 IOT-USD   -0.04%      431   59 ++     selling   2.4826  3  241.21893874 IOT    7.00 USD  -24.33%   -6.27%
sell order completed at 2018-01-30 09:57:10:

238.80674935 IOT at 2.48470 USD
[...]
2018-01-30 11:30:00  2.53000 IOT-USD   +0.20%    41092   69 +++       sell   2.4847  4    2.41218939 IOT  599.03 USD  -24.46%   -8.13%
2018-01-30 11:33:00  2.52800 IOT-USD   -0.08%    34128   67 +++       sell   2.4148  4    2.41218939 IOT  599.03 USD  -24.46%   -8.06%
                                                                             ^^^^^^
2018-01-30 11:36:00  2.49000 IOT-USD   -1.51%  107.21k     - 47       sell   2.4148  4    2.41218939 IOT  599.03 USD  -24.47%   -6.67%

You can see the last trade value price jumping around the my_trades array. Any clues? Maybe a call to my_trades.slice() missing somewhere before manipulation (sorting?) with a copy of my_trades?

[laloch]

@defkev : The bug is in dashboard.ejs on master branch where you do my_trades.reverse(). It is probably already fixed by using XMLHttpRequest to obtain the trade data on unstable branch.

[defkev]

my_trades are no longer reversed but sorted in unstable

The array is populated by the time a trade got executed but we want it to show up by date.

This of course only applies to the dashboard as the array will always be old -> new

[laloch]

The point is that you should never ever touch my_trades directly unless you are perfectly sure that what you have is my_trades deep copy. If you need to reverse or sort it, do it like my_trades.slice().sort(...) instead. If you manipulate the array directly, you are breaking the engine, because of the brain damaged way the JS arrays work.
There should be some sort of API preventing extensions to fiddle with the internal structures directly.

Edit: The master branch needs a hotfix for this. In the present state the dashboard breaks pretty much everything that depends on the my_trades state (no offense, @defkev).

[defkev]

As i said, this only applies to the dashboard and never touches the array.

Its sorting the object exposed by the api under /trades in ejs not the array of the backend in node.

[laloch]

Its sorting the object exposed by the api under /trades in ejs not the array of the backend in node.

Not on the master branch. On unstable the dashboard is decoupled via XMLHttpRequest request to /trades. On master, however, the array is accessed directly. Try for yourself. I bet, that you can even do <% my_trades.push({size:0, price:0, time:0}) %> and the new trade will be immediately visible from the engine.js.

[defkev]

Again, as i said

sorted in unstable

But if what you say is true this would indeed be a huge security risk as the data exposed by /trades should be read-only, at least until we have some kind of API authentication in place.

Let me take a look.

[laloch]

I have just tried myself. I've added <% my_trades.push({size:1, price:1, type:"buy", time:0}) %> to dashboard.ejs (master branch version) and the console immediately displayed one trade with +140.07% profit.

[laloch]

Btw, I can confirm that with the below patch applied, the last_trade stopped altering and consequently stop loss order stopped firing at "random".

diff --git a/templates/dashboard.ejs b/templates/dashboard.ejs
index 34301cd..7bd29d5 100644
--- a/templates/dashboard.ejs
+++ b/templates/dashboard.ejs
@@ -209,7 +209,7 @@
                                 </tr>
                                 <% } %>
                                 <% if (my_trades) { %>
-                                <% my_trades.reverse().forEach(function(trade){ %>
+                                <% my_trades.slice().reverse().forEach(function(trade){ %>
                                 <tr>
                                     <td><span class='text-<% if (trade.type == "buy") { %>success<% } else { %>danger<% } %>'><%= trade.type.toUpperCase() %></td>
                                     <td><%= trade.size %> <%= asset.toUpperCase() %></td>

[defkev]

This is indeed bad and absolutely not what we want.

I have zero experience with express and wonder if this is document somewhere.

Thanks for reporting it 👍

Let me prep a PR.