http2 websockets leaks while using open ssl for ping and pong

[kerdemdemir]

I am listening ~100 web sockets from binance.com to keep up with live transactions(every single buy and sell order).

I have been having memory leak problems for a long time and have to restart my application after 3-4 hours. Because I am running out of my 32gb ram.

Now I want to listening order book data as well(supply and demand book) but my applications just run out of memory after 5 mins.

I use many different tools to find where is leak. The best was gprefd. I found out there were too many allocations from OpenSSL and Arsd.

I used gdb and put breakpoints to malloc to confirm that and the stack trace always showed OpenSSLSocket's send and receive.

I changed the "int pingFrequency = 5000;" to a very big number and now I can run my application for 6-8 hours without running out of memory. But the memory leak still continues because I just controlled the pings that we send but also my server(binance.com) sends me pong approximately every 3 minutes. And pongs uses the same OpenSSLSocket class and its leaking functions send&recieve.

I can attach the gdb stack outputs and gpref results if it is requested.

Thanks for the awesome Arsd library, I removed all vibe.d stuff and replaced it with Arsd :)

[adamdruppe]

I might have forgotten to call some openssl cleanup function... post what you have and i can see.

[kerdemdemir]

So stack looks like:

Breakpoint 1 at 0x7aa0186ad640: malloc. (48 locations)
(gdb) c
Continuing.
[Switching to Thread 0x7a9ffa6006c0 (LWP 767438)]

Thread 16 "dmarketcalls" hit Breakpoint 1.2, 0x00007aa019038cc0 in tc_malloc () from /lib/x86_64-linux-gnu/libtcmalloc.so.4
(gdb) bt
#0 0x00007aa019038cc0 in tc_malloc () from /lib/x86_64-linux-gnu/libtcmalloc.so.4
#1 0x00007aa018c237c5 in CRYPTO_zalloc () from /lib/x86_64-linux-gnu/libcrypto.so.3
#2 0x00007aa01973e463 in ?? () from /lib/x86_64-linux-gnu/libssl.so.3
#3 0x00007aa01977113c in ?? () from /lib/x86_64-linux-gnu/libssl.so.3
#4 0x00007aa019772361 in ?? () from /lib/x86_64-linux-gnu/libssl.so.3
#5 0x00007aa019752b4b in SSL_write () from /lib/x86_64-linux-gnu/libssl.so.3
#6 0x00006011327da290 in arsd.http2.OpenSSL.opDispatch!("SSL_write").opDispatch!(arsd.http2.SSL*, const(void), uint).opDispatch(arsd.http2.SSL, const(void), uint) (__param_2=6,
__param_1=0x7a9ffa5fd610, __param_0=0x60113c3fc000) at source/http2.d:3686
#7 0x00006011327d41bf in arsd.http2.OpenSslSocket.send(scope const(void)[], std.socket.SocketFlags) (this=0x7aa0117278d0, flags=, buf=...) at source/http2.d:4004
#8 0x00006011327d41fb in arsd.http2.OpenSslSocket.send(scope const(void)[]) (this=0x7aa0117278d0, buf=...) at source/http2.d:4024
#9 0x00006011327d6c12 in arsd.http2.WebSocket.llsend(ubyte[]) (this=0x7aa011726a00, d=...) at source/http2.d:4961
#10 0x00006011327d8e8e in arsd.http2.WebSocketFrame.send(scope void(ubyte[]) delegate) (this=..., llsend=...) at source/http2.d:5875
#11 0x00006011327d7499 in arsd.http2.WebSocket.pong(in ubyte[]) (this=0x7aa011726a00, data=...) at source/http2.d:5201
#12 0x00006011327d7caf in arsd.http2.WebSocket.processOnce() (this=0x7aa011726a00, __HID215=0x7a9ffa5fd920) at source/http2.d:5362
#13 0x00006011327d8066 in arsd.http2.WebSocket.readyToRead(arsd.http2.WebSocket) (sock=0x7aa011726a00) at source/http2.d:5472
#14 0x00006011327d84b2 in arsd.http2.WebSocket.eventLoop(shared(bool)) (localLoopExited=0x7aa00e9f18a0) at source/http2.d:5583
#15 0x00006011326c14b5 in Client.SocketHelper.ArsdMultiThreadSocket.ArsdMultiThreadSocket.InitCurrencies().captureFuction(int).__lambda2() (__capture=0x7aa00cc3e930)
at source/Client/SocketHelpers/ArsdMultiThreadSocket.d:71
#16 0x00006011326c14e1 in Client.SocketHelper.ArsdMultiThreadSocket.ArsdMultiThreadSocket.InitCurrencies().__lambda5() (__capture=0x7aa00cc778c0)
at source/Client/SocketHelpers/ArsdMultiThreadSocket.d:80
#17 0x00006011329d727d in core.thread.context.Callable.opCall() ()
#18 0x00006011329d6d5b in thread_entryPoint ()
#19 0x00007aa01869ca94 in start_thread (arg=) at ./nptl/pthread_create.c:447
#20 0x00007aa018729c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

I put also break point to free which triggers time to time but way more less than mallocs:

Thread 24 "dmarketcalls" hit Breakpoint 2.2, 0x00007aa019036bc0 in tc_free () from /lib/x86_64-linux-gnu/libtcmalloc.so.4
(gdb) bt
#0 0x00007aa019036bc0 in tc_free () from /lib/x86_64-linux-gnu/libtcmalloc.so.4
#1 0x00007aa01973e8cd in ?? () from /lib/x86_64-linux-gnu/libssl.so.3
#2 0x00007aa019771b23 in ?? () from /lib/x86_64-linux-gnu/libssl.so.3
#3 0x00007aa019772361 in ?? () from /lib/x86_64-linux-gnu/libssl.so.3
#4 0x00007aa019752b4b in SSL_write () from /lib/x86_64-linux-gnu/libssl.so.3
#5 0x00006011327da290 in arsd.http2.OpenSSL.opDispatch!("SSL_write").opDispatch!(arsd.http2.SSL*, const(void), uint).opDispatch(arsd.http2.SSL, const(void), uint) (__param_2=6,
__param_1=0x7a9fff5fd610, __param_0=0x601141942000) at source/http2.d:3686
#6 0x00006011327d41bf in arsd.http2.OpenSslSocket.send(scope const(void)[], std.socket.SocketFlags) (this=0x7a9fda9b1c30, flags=, buf=...) at source/http2.d:4004
#7 0x00006011327d41fb in arsd.http2.OpenSslSocket.send(scope const(void)[]) (this=0x7a9fda9b1c30, buf=...) at source/http2.d:4024
#8 0x00006011327d6c12 in arsd.http2.WebSocket.llsend(ubyte[]) (this=0x7a9fda99b600, d=...) at source/http2.d:4961
#9 0x00006011327d8e8e in arsd.http2.WebSocketFrame.send(scope void(ubyte[]) delegate) (this=..., llsend=...) at source/http2.d:5875
#10 0x00006011327d7499 in arsd.http2.WebSocket.pong(in ubyte[]) (this=0x7a9fda99b600, data=...) at source/http2.d:5201
#11 0x00006011327d7caf in arsd.http2.WebSocket.processOnce() (this=0x7a9fda99b600, __HID215=0x7a9fff5fd920) at source/http2.d:5362
#12 0x00006011327d8066 in arsd.http2.WebSocket.readyToRead(arsd.http2.WebSocket) (sock=0x7a9fda99b600) at source/http2.d:5472
#13 0x00006011327d84b2 in arsd.http2.WebSocket.eventLoop(shared(bool)) (localLoopExited=0x7aa00e9f18a0) at source/http2.d:5583
#14 0x00006011326c14b5 in Client.SocketHelper.ArsdMultiThreadSocket.ArsdMultiThreadSocket.InitCurrencies().captureFuction(int).__lambda2() (__capture=0x7aa00cc45280)
at source/Client/SocketHelpers/ArsdMultiThreadSocket.d:71
#15 0x00006011326c14e1 in Client.SocketHelper.ArsdMultiThreadSocket.ArsdMultiThreadSocket.InitCurrencies().__lambda5() (__capture=0x7aa00cc778c0)
at source/Client/SocketHelpers/ArsdMultiThreadSocket.d:80
#16 0x00006011329d727d in core.thread.context.Callable.opCall() ()
#17 0x00006011329d6d5b in thread_entryPoint ()
#18 0x00007aa01869ca94 in start_thread (arg=) at ./nptl/pthread_create.c:447
#19 0x00007aa018729c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

You can see a glimbs of malloc to free ratio here.

When my memory goes super high above 16gb I used https://gperftools.github.io/gperftools/heapprofile.html few times and so most of the mallocs were coming from pings. That was before I solve the issue with ping with my hack.
Now I bet I would see pong which I can not stop because my server documentation "https://developers.binance.com/docs/binance-spot-api-docs/web-socket-api" says if I dont respond pongs with in 10 minutes period they will shutdown the connection. So I can not unfortunately hack pongs.

Best Regards
Erdem

[adamdruppe]

huh so it is right inside the openssl functions. i know they keep some pieces around to chunk it right but.... huh

might have to check the docs again and see what im missing

[kerdemdemir]

Hi @adamdruppe,

Claude AI suggested that fixes in http2.d:

After those changes, my app's memory usage still increases with time but I think it slowed down. Before the changes after 4-6 hours, I was reaching 25gb ram usage now, I ran the app for 10hours, and I was using 10gb ram. That was the first day I ran the app after the changes. I will come up with better numbers for before and after. But maybe changes are pointless and not useful.

Do you think they might have some value?

[adamdruppe]

I don't think that specifically since it calls socket.close when it gets a close event (see line 5485 and a couple other places) so that should be covered.

There is a function freeSsl that is called from the destructor that is supposed to do openssl stuff but maybe the destructor is never running, if the socket is not unregistered, it will never be free in the GC's eyes.

So... i could have missed a spot in unregistering. Freeing that ssl stuff prolly shouldn't wait for the GC anyway, once it is closed and unregistered it could be done immediately i believe. Or an exception being thrown in an onclose handler would cancel that unregister, that could be it too.

Do you open a bunch of connections or just one?

[adamdruppe]

that llclose isn't supposed to call socket.close yet because it waits for the other side to acknowledge it with a close packet: https://datatracker.ietf.org/doc/html/rfc6455#section-7.1.1

[kerdemdemir]

I open ~300 connections(for each trade pair in binance.com), and I run 24 threads to handle all these connections. Each thread is running ~300/24 sockets. I have logs in onclose, but I see an increase in memory usage, even though the onclose handle is not being called. I will come up with precise numbers about before and after in a couple of days.

[adamdruppe]

there's a receive buffer that grows if messages are large, do you have any big individual messages too?

i wonder if i can reproduce this program locally here

[adamdruppe]

taking another look at the code here, each websocket send (including pings and pongs) do allocate small arrays, but the GC should be picking them up quickly. SSL_write doesn't say anything about having to free things there, it is supposed to be auto managed.

I have this discord bot that uses websocket client and runs a long time.... memory appears stable after startup.

is there any way you can post a full program that demonstrates the problem?

[adamdruppe]

my one bit went from 12 MB to 18 MB in the first couple minutes. Since then over the last 5 hours it has crept up to about 22 MB. Interesting...

[adamdruppe]

one idea would be if it is a bunch of new websockets being created and reconnected but not generating enough trash to trigger the GC of the old ones, maybe that's keep some openssl junk around. just wish i could produce the problem reliably in minutes lol. but trying to call freeSsl in the close method to see what happens. the memory pattern doesn't look much different...

[adamdruppe]

After overnight it is still at just a bit over 22 MB. so maybe this helped? hard to say for sure.

[adamdruppe]

97e560b

this commit might help, the freeSsl call in the close() function has given more stability to my one bot program. Still a little over 22 MB two days later. You might try it too.

[kerdemdemir]

I am super sorry, I couldn't come up with a minimal example yet I will come up with it asap.

I have been running my app without your latest commit and mem usage in three different times was

103069 erdem 20 0 13.4g 13.0g 24912 S 16.9 41.7 133:30.99 dmarketcalls
103069 erdem 20 0 16.2g 15.7g 24912 S 16.9 50.5 188:48.85 dmarketcalls
103069 erdem 20 0 16.7g 16.2g 24912 S 14.0 52.1 209:37.70 dmarketcalls

I copy pasted latest http2 to my project I am super excited about the commit. I will let it run and post the mem usage results.

Thanks a lot for your responses yet again sorry in my half

[kerdemdemir]

Hi I come up with minimal example which loads ~300 websockets with 12 thread usings arsd.

https://github.com/kerdemdemir/MinimalBinanceWebSockets

dub run is enough to run it.

Memory seems rock solid for now so maybe problem was somewhere else I will keep it running for a longer time and see what will happen. Maybe it can be useful as an example also.