Websocket disconnecting

daryl552007 commented 4 years ago

Hi Bmino,

as mentioned on the previous issue thread. I keep on getting disconnected then reconnecting again. You answered it could be an internet connection problem, is it mine if I run it once(npm start) instead of forever running the script? Or is it on my lightsail instance?

PS, I am running this on our lightsail instance by using SSH.

daryl552007 commented 4 years ago

Hi Bmino,

I have already created a newer instance closer to Binance I assume after they suggested a region to connect the API from. However, I am still having this error. Though not as frequent as before. Is there a way for me to stop the script if this happens and then run it again automatically?

bmino commented 4 years ago

Hey, how long between starting the app until the disconnected/reconnected begins to occur? Is it consistently about the same amount of time?

bmino commented 4 years ago

If you want to restart the app when it crashes you can use something like pm2 or forever.

Be advised though that if the app is failing on startup this will continually restart (if used irresponsibly) your app exhausting your weighted API limits

daryl552007 commented 4 years ago

Hi Bmino,

thanks for the tips. Yes I will watch out with exhausting the API limits.

for the time until I get disconnected, its usually around 10 -15 minutes I think, I am not sure if they get really reconnected as I just stopped the script and restart it again. The screen gets full with those Disconnected and reconnecting messages.

Also I am seeing this in the logs

bmino commented 4 years ago

No worries about the dots in your logs. Every time the program is restarted, that is printed to distinguish one execution from previous executions.

Every time I have encountered websockets disconnecting/reconnecting during execution, it has occurred due to an hiccup in internet connection. Other possibilities could include:

Exceeding the 5 incoming messages per second websocket limit
Maxing out cpu resources
Timing out an inactive websocket connection at 24 hours

daryl552007 commented 4 years ago

Thanks Bmino,

I am using lightsail, do you think that could be the reason? What other hosting do you suggest that have ran good latency for this scripts purpose?

hathehuyen commented 4 years ago

I have the same issue

bmino commented 4 years ago

I am unfamiliar with lightsail in particular. I've used simple aws ec2 instances, installed nodejs, and cloned the app, configured it, and then started the bot

kimasplund commented 4 years ago

This seems fairly good in general but it really needs a connection limiter. That would prevent the temporary banns from api connection. Most other bots have it in config so you can set the ms limit

wadalsahafa commented 4 years ago

Hi Bmino It will be great if you can add HITBTC as a supported exchange. I think it will work there. THanks

dlasher commented 4 years ago

I may open a separate ticket on this, but I've been running up against this limit often, and I've done a LOT of tweaking to try to work around this. Things I've tried:

More CPU - running it on a 32 core box
Less depth, depending on the SYMBOL, sometimes dropping to 10 depth isn't enough
Using VMHost near binance API - lower latency helps
Investment min/max/step - less steps helps a ton
TCP Stack tuning - helps a healthy amount

In theory, a 8 core dedicated VM, sitting in Singapore/Toyko, with <20ms response to api.binance.com, should be able to handle this without sockets timing out, assuming Binance is keeping up.. but it can't given what appears to be safe/common-sense config options.

I do wonder, from a socket standpoint, if the answer is less websockets open? One of the other arb-bots I've played with manages to do everything over a single WS, which at least avoids -this- problem.. (but it has other problems, lol)

As an aside, if it finds XX triangle relationships, why does it open max amount of websockets?


Found 625/882 currently trading tickers
Found 158 triangular relationships
Checking configuration ...
Checking balances ...
Opening 625 depth websockets ...```

bmino commented 4 years ago

I am investigating and working on a potential solution to this again

bmino commented 4 years ago

@dlasher in your example 158 triangular relationships are found, but let's say that only 1 relationship was found. We can call that relationship A -> B -> C. This requires AB, BC, and CA which would require three websockets to track those order books. This is why you see more web socket connections than triangular relationships

I'm about to put out a release which could address this issue but am still investigating some other potential causes

dlasher commented 4 years ago

@bmino - that makes sense, I think. experimented with reducing the whitelist down, and the number of sockets still seems more than 3x.

Found 641/906 currently trading tickers Found 50 triangular relationships Checking configuration ... Checking balances ... Opening 189 depth websockets ...

Assuming ZERO overlap, that's still 3.78x the number of relationships. In practice there should be a lot of overlap.

Trying this out visually:

ETH-TRX-BTC-ETH - Track ETH-TRX, TRX-BTC and BTC-ETH
ETH-ADA-BTC-ETH - Track ETH-ADA, ADA-BTC and BTC-ETH
ETH-LINK-BTC-ETH - Track ETH-LINK, LINK-BTC and BTC-ETH

so for those (3) triangle relationships, I see 7 separate websockets.

Am I following the logic right?

In other words CA gets reused, and you're tracking lots of unique AB and BC? (2 more triangle, + 1 shared?) That should generate around 102 Websockets for 50 relationships?

bmino commented 4 years ago

Seems like a valid concern! Will you please file a separate issue to track that?

dlasher commented 4 years ago

Happy to. I'll copy/paste a bit.

dlasher commented 4 years ago

Quick update:

Testing against 5.5.1, the "bundle" option gives me the option to scale things back/forth see where we're timing out.

On the assumption that perhaps some of the lesser coins actually we're doing any trading during the interval, I increased to 25 per bundle. Nope, still fails. 👍

["8/31/2020, 6:51:56 PM"] INFO : Terminating inactive/broken WebSocket: 1044937290 ["8/31/2020, 6:52:09 PM"] INFO : WebSocket closed: 1044937290 (1006) ["8/31/2020, 6:52:09 PM"] INFO : WebSocket reconnecting: 1044937290... ["8/31/2020, 6:52:09 PM"] INFO : CombinedStream: Subscribed to [1044937290] sxpbtc@depth@100ms/sxpbnb@depth@100ms/snxbtc@depth@100ms/snxbnb@depth@100ms/mkrbtc@depth@100ms/mkrbnb@depth@100ms/balbtc@depth@100ms/balbnb@depth@100ms/yfibtc@depth@100ms/yfibnb@depth@100ms/jstbtc@depth@100ms/jstbnb@depth@100ms/srmbtc@depth@100ms/srmbnb@depth@100ms/antbtc@depth@100ms/antbnb@depth@100ms/crvbtc@depth@100ms/crvbnb@depth@100ms/dotbtc@depth@100ms/dotbnb@depth@100ms

==> /usr/src/binance-triangle-arbitrage/logs/performance.log <== ["8/31/2020, 6:52:10 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to SXP using SXPBTC ["8/31/2020, 6:52:10 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to SNX using SNXBTC ["8/31/2020, 6:52:10 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to MKR using MKRBTC ["8/31/2020, 6:52:10 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to BAL using BALBTC ["8/31/2020, 6:52:10 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to YFI using YFIBTC ["8/31/2020, 6:52:10 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to JST using JSTBTC ["8/31/2020, 6:52:10 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to SRM using SRMBTC ["8/31/2020, 6:52:10 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to ANT using ANTBTC ["8/31/2020, 6:52:10 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to CRV using CRVBTC ["8/31/2020, 6:52:10 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to DOT using DOTBTC ["8/31/2020, 6:52:10 PM"] WARN : Completed 71/81 (87.7%) calculations in 558 ms ["8/31/2020, 6:52:11 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to SXP using SXPBTC ["8/31/2020, 6:52:11 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to SNX using SNXBTC ["8/31/2020, 6:52:11 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to MKR using MKRBTC ["8/31/2020, 6:52:11 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to BAL using BALBTC ["8/31/2020, 6:52:11 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to YFI using YFIBTC ["8/31/2020, 6:52:11 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to JST using JSTBTC ["8/31/2020, 6:52:11 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to SRM using SRMBTC ["8/31/2020, 6:52:11 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to ANT using ANTBTC ["8/31/2020, 6:52:11 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to CRV using CRVBTC ["8/31/2020, 6:52:11 PM"] WARN : Ask depth (0) too shallow to convert 0.001 BTC to DOT using DOTBTC ["8/31/2020, 6:52:11 PM"] WARN : Completed 71/81 (87.7%) calculations in 496 ms

So I'm puzzled. throwing more cores at it (up to 32) doesn't solve it. throwing really fast single cores (4ghz AWS Z1D) at it, doesn't solve it. lower latency doesn't solve it (VPS in Toyko, 2ms response time.) Increasing the bundle doesn't solve it. decreasing the bundle doesn't solve it.

Seems like the only thing that DOES, is reducing the depth, which then doesn't give enough to make trades with some of the lesser coins. I guess askdepth 20 is better than askdepth 0.

["8/31/2020, 7:00:17 PM"] WARN : Bid depth (20) too shallow to convert 0.4999999999999929 XTZ to BNB using XTZBNB ["8/31/2020, 7:00:23 PM"] WARN : Bid depth (20) too shallow to convert 0.5100000000000017 NEO to BNB using NEOBNB ["8/31/2020, 7:00:24 PM"] WARN : Bid depth (20) too shallow to convert 0.17000000000000187 NEO to BNB using NEOBNB ["8/31/2020, 7:00:28 PM"] WARN : Bid depth (20) too shallow to convert 0.49999999999993605 XTZ to BNB using XTZBNB ["8/31/2020, 7:00:32 PM"] WARN : Bid depth (20) too shallow to convert 0.030000000000004856 NEO to BNB using NEOBNB ["8/31/2020, 7:00:32 PM"] WARN : Bid depth (20) too shallow to convert 1.5999999999999588 XTZ to BNB using XTZBNB ["8/31/2020, 7:00:33 PM"] WARN : Bid depth (20) too shallow to convert 0.04000000000000287 NEO to BNB using NEOBNB ["8/31/2020, 7:00:33 PM"] WARN : Bid depth (20) too shallow to convert 1.5999999999999588 XTZ to BNB using XTZBNB

So at this point, the only thing I have to go on, is the fact that when it's running, with depth=50 or depth=100, ONE of the threads is flatlined at 100%, no matter the platform I run it on. So, what else can we thread out?

dlasher commented 4 years ago

I suspect investment range might be behind what we're seeing. This is how mine was configured:

"INVESTMENT": {
    "BASE": "BTC",
    "MIN": 0.0001,
    "MAX": 0.1,
    "STEP": 0.0001
}

bmino commented 4 years ago

Disconnects occur when the heartbeat sends a "ping" and does not receive a "pong" before the next heartbeat in 30 seconds.

I've been studying this behavior to better understand this issue. A couple observations:

The "pong" frame often comes in later than 30 seconds but even increasing the heatbeat interval to 3 minutes, this still occurs
Terminating a websocket often takes upwards of a few minutes? Wow!
Changing the depth sockets depth to 20 and update frequency from 100ms to 1000ms and still having this issue
This happens more frequently on machines with less cpu power / internet

I have been running a c5n.large aws ec2 instance in the Tokyo region with the following stats. This has not seen a websocket disconnect in the last 12 hours of running. I am also using Ubuntu 20.04, but I do not think this is affecting disconnects.

Instance type	vCPUs	Memory (GiB)	Storage (GB)	Network
c5n.large	2	5.25	EBS only	Up to 25 Gigabit

My leading theory is that the machine running the bot is overwhelmed handling incoming websocket data in the time allowed between calculation cycles. Only one cpu core is really being leveraged. I gotta think internet speed plays a role in the disconnects but haven't isolated that yet

dlasher commented 3 years ago

Nice work on performance tracking, seeing a pretty wide variance of API performance over time. Here's the last 2h:

["9/17/2020, 5:24:01 PM"] DEBUG: API Latency: 97 ms ["9/17/2020, 5:26:01 PM"] DEBUG: API Latency: 232 ms ["9/17/2020, 5:28:01 PM"] DEBUG: API Latency: 278 ms ["9/17/2020, 5:30:01 PM"] DEBUG: API Latency: 93 ms ["9/17/2020, 5:32:01 PM"] DEBUG: API Latency: 200 ms ["9/17/2020, 5:34:01 PM"] DEBUG: API Latency: 192 ms ["9/17/2020, 5:36:01 PM"] DEBUG: API Latency: 90 ms ["9/17/2020, 5:38:01 PM"] DEBUG: API Latency: 155 ms ["9/17/2020, 5:40:01 PM"] DEBUG: API Latency: 70 ms ["9/17/2020, 5:42:01 PM"] DEBUG: API Latency: 76 ms ["9/17/2020, 5:44:01 PM"] DEBUG: API Latency: 194 ms ["9/17/2020, 5:46:01 PM"] DEBUG: API Latency: 94 ms ["9/17/2020, 5:48:01 PM"] DEBUG: API Latency: 93 ms ["9/17/2020, 5:50:01 PM"] DEBUG: API Latency: 96 ms ["9/17/2020, 5:52:01 PM"] DEBUG: API Latency: 94 ms ["9/17/2020, 5:54:01 PM"] DEBUG: API Latency: 160 ms ["9/17/2020, 5:56:01 PM"] DEBUG: API Latency: 203 ms ["9/17/2020, 5:58:01 PM"] DEBUG: API Latency: 159 ms ["9/17/2020, 6:00:01 PM"] DEBUG: API Latency: 147 ms ["9/17/2020, 6:02:01 PM"] DEBUG: API Latency: 267 ms ["9/17/2020, 6:04:01 PM"] DEBUG: API Latency: 170 ms ["9/17/2020, 6:06:01 PM"] DEBUG: API Latency: 99 ms ["9/17/2020, 6:08:01 PM"] DEBUG: API Latency: 134 ms ["9/17/2020, 6:10:01 PM"] DEBUG: API Latency: 98 ms ["9/17/2020, 6:12:01 PM"] DEBUG: API Latency: 26 ms ["9/17/2020, 6:14:01 PM"] DEBUG: API Latency: 115 ms ["9/17/2020, 6:16:01 PM"] DEBUG: API Latency: 108 ms ["9/17/2020, 6:18:01 PM"] DEBUG: API Latency: 62 ms ["9/17/2020, 6:20:01 PM"] DEBUG: API Latency: 94 ms ["9/17/2020, 6:22:01 PM"] DEBUG: API Latency: 80 ms ["9/17/2020, 6:24:01 PM"] DEBUG: API Latency: 127 ms ["9/17/2020, 6:26:01 PM"] DEBUG: API Latency: 178 ms ["9/17/2020, 6:28:01 PM"] DEBUG: API Latency: 207 ms ["9/17/2020, 6:30:01 PM"] DEBUG: API Latency: 112 ms ["9/17/2020, 6:32:01 PM"] DEBUG: API Latency: 88 ms ["9/17/2020, 6:34:01 PM"] DEBUG: API Latency: 102 ms ["9/17/2020, 6:36:01 PM"] DEBUG: API Latency: 85 ms ["9/17/2020, 6:38:01 PM"] DEBUG: API Latency: 116 ms ["9/17/2020, 6:40:01 PM"] DEBUG: API Latency: 148 ms ["9/17/2020, 6:42:01 PM"] DEBUG: API Latency: 147 ms ["9/17/2020, 6:44:02 PM"] DEBUG: API Latency: 230 ms ["9/17/2020, 6:46:02 PM"] DEBUG: API Latency: 193 ms ["9/17/2020, 6:48:01 PM"] DEBUG: API Latency: 97 ms ["9/17/2020, 6:50:01 PM"] DEBUG: API Latency: 32 ms ["9/17/2020, 6:52:02 PM"] DEBUG: API Latency: 193 ms ["9/17/2020, 6:54:02 PM"] DEBUG: API Latency: 187 ms ["9/17/2020, 6:56:02 PM"] DEBUG: API Latency: 107 ms ["9/17/2020, 6:58:02 PM"] DEBUG: API Latency: 88 ms ["9/17/2020, 7:00:02 PM"] DEBUG: API Latency: 188 ms ["9/17/2020, 7:02:02 PM"] DEBUG: API Latency: 94 ms ["9/17/2020, 7:04:02 PM"] DEBUG: API Latency: 140 ms ["9/17/2020, 7:06:02 PM"] DEBUG: API Latency: 141 ms ["9/17/2020, 7:08:02 PM"] DEBUG: API Latency: 37 ms ["9/17/2020, 7:10:02 PM"] DEBUG: API Latency: 231 ms ["9/17/2020, 7:12:02 PM"] DEBUG: API Latency: 87 ms ["9/17/2020, 7:14:02 PM"] DEBUG: API Latency: 86 ms ["9/17/2020, 7:16:02 PM"] DEBUG: API Latency: 156 ms ["9/17/2020, 7:18:02 PM"] DEBUG: API Latency: 111 ms ["9/17/2020, 7:20:02 PM"] DEBUG: API Latency: 172 ms ["9/17/2020, 7:22:02 PM"] DEBUG: API Latency: 142 ms ["9/17/2020, 7:24:02 PM"] DEBUG: API Latency: 158 ms

This from a VPC sitting 2ms away from AWS in Toyko to Binance API

dlasher commented 3 years ago

["9/17/2020, 7:46:02 PM"] DEBUG: Calculation cycle average speed: 24.44 ms ["9/17/2020, 7:46:02 PM"] DEBUG: CPU Load: 26% [11%,16%,28%,16%] ["9/17/2020, 7:46:02 PM"] DEBUG: Memory Usage: 2.3 GB ["9/17/2020, 7:46:02 PM"] DEBUG: Network Usage: 51.2 KBps (down) and 31.6 KBps (up) ["9/17/2020, 7:46:02 PM"] DEBUG: API Latency: 35 ms ["9/17/2020, 7:48:02 PM"] DEBUG: Calculation cycle average speed: 25.24 ms ["9/17/2020, 7:48:02 PM"] DEBUG: CPU Load: 25% [6%,4%,53%,10%] ["9/17/2020, 7:48:02 PM"] DEBUG: Memory Usage: 2.3 GB ["9/17/2020, 7:48:02 PM"] DEBUG: Network Usage: 48.4 KBps (down) and 25.6 KBps (up) ["9/17/2020, 7:48:02 PM"] DEBUG: API Latency: 139 ms

100ms swing in latency, and it's not network load on the VPC, it's not CPU load, it's not RAM load. I think the exchange is having a hard(er) time keeping up.

bmino commented 3 years ago

I've finally got it! The metric to look for was cpu time spent analyzing the market. This grows as a percentage of overall time until not enough free cpu cycles are left. At about 75% websockets will get disconnected.

Fixes:

More efficient depth parsing (stay tuned)
Less investment quantities checked
Shallow depth caches
Stronger cpu

dlasher commented 3 years ago

I've finally got it! The metric to look for was cpu time spent analyzing the market. This grows as a percentage of overall time until not enough free cpu cycles are left. At about 75% websockets will get disconnected.

Fantastic! Looking forward to your fixes.

bmino commented 3 years ago

Check out the new v6.0.0!

dlasher commented 3 years ago

Checking logs, we got another trade, but .. looks backward again..

["10/19/2020, 2:29:34 PM"] INFO : Attempting to execute BTC-DASH-ETH with an age of 68 ms and expected profit of 0.0727% ["10/19/2020, 2:29:34 PM"] INFO : Buying 5.725 DASHBTC @ market price ["10/19/2020, 2:29:34 PM"] INFO : Successfully bought 5.72500000 DASHBTC @ a quote of 0.03417825 in 44 ms ["10/19/2020, 2:29:34 PM"] INFO : Selling 5.725 DASHETH @ market price ["10/19/2020, 2:29:34 PM"] INFO : Successfully sold 5.72500000 DASHETH @ a quote of 1.04212175 in 23 ms ["10/19/2020, 2:29:34 PM"] INFO : Selling 1.042 ETHBTC @ market price ["10/19/2020, 2:29:34 PM"] INFO : Successfully sold 1.04200000 ETHBTC @ a quote of 0.03399837 in 23 ms ["10/19/2020, 2:29:34 PM"] INFO : Executed BTC-DASH-ETH position in 97 ms ["10/19/2020, 2:29:34 PM"] DEBUG: DASHBTC Stats: ["10/19/2020, 2:29:34 PM"] DEBUG: Expected Conversion: 0.03399505 BTC into 5.72500000 DASH @ 0.00593800 ["10/19/2020, 2:29:34 PM"] DEBUG: Observed Conversion: 0.03417825 BTC into 5.72500000 DASH @ 0.00597000 ["10/19/2020, 2:29:34 PM"] DEBUG: Conversion Error: 0.53890199% ["10/19/2020, 2:29:34 PM"] DEBUG: ["10/19/2020, 2:29:34 PM"] DEBUG: DASHETH Stats: ["10/19/2020, 2:29:34 PM"] DEBUG: Expected Conversion: 5.72500000 DASH into 1.04504150 ETH @ 5.47825134 ["10/19/2020, 2:29:34 PM"] DEBUG: Observed Conversion: 5.72500000 DASH into 1.04212175 ETH @ 5.49359996 ["10/19/2020, 2:29:34 PM"] DEBUG: Conversion Error: 0.28017360% ["10/19/2020, 2:29:34 PM"] DEBUG: ["10/19/2020, 2:29:34 PM"] DEBUG: ETHBTC Stats: ["10/19/2020, 2:29:34 PM"] DEBUG: Expected Conversion: 1.04500000 ETH into 0.03409626 BTC @ 30.64852274 ["10/19/2020, 2:29:34 PM"] DEBUG: Observed Conversion: 1.04200000 ETH into 0.03399837 BTC @ 30.64852815 ["10/19/2020, 2:29:34 PM"] DEBUG: Conversion Error: 0.00001765% ["10/19/2020, 2:29:34 PM"] INFO : ["10/19/2020, 2:29:34 PM"] INFO : BTC delta: -0.00017988 (-0.5263%) ["10/19/2020, 2:29:34 PM"] INFO : DASH delta: 0.00000000 ( 0.0000%) ["10/19/2020, 2:29:34 PM"] INFO : ETH delta: 0.00012175 ( 0.0117%) ["10/19/2020, 2:29:34 PM"] INFO : BNB fees: -0.02931882 ["10/19/2020, 2:29:34 PM"] INFO : ["10/23/2020, 6:55:42 PM"] INFO : -------------------------------------------------- ["10/23/2020, 6:55:57 PM"] INFO : Initialized

dlasher commented 3 years ago

Grabbed new version btw, will monitor.

bmino commented 3 years ago

Yikes, that slipped through. Filed #117 to track that

bmino commented 3 years ago

Is anybody still experiencing disconnecting websockets?

bmino / binance-triangle-arbitrage

Websocket disconnecting #98