Websocket timeout issues #2026

donovanhide · 2017-02-22T20:15:07Z

With 0.50.2 repeated calls to ledger_data whilst also streaming the ledger and transaction streams leads to timeouts in the Server code in rippled with log_level set to trace:

2017-Feb-22 20:10:35 Server:TRC Websocket received '
{
        "binary" : true,
        "command" : "ledger_data",
        "id" : 39,
        "ledger" : 27861637,
        "marker" : "1AC61580EF42AA58D69059995313F05C5342E6AC2BA6A46A51EFB508C0F79C75"
}
'
2017-Feb-22 20:10:35 Server:TRC Websocket received '
{
        "binary" : true,
        "command" : "ledger_data",
        "id" : 40,
        "ledger" : 27861637,
        "marker" : "1B7EA1321C09D8421502B0A63EAD615EA3CB92EEB6393909312EA76C002C7289"
}
'
2017-Feb-22 20:10:35 Server:TRC ##22 timer: Connection timed out
2017-Feb-22 20:10:35 Server:TRC ##23 read: End of file
2017-Feb-22 20:10:35 Server:TRC ##24 write: Broken pipe

Problem is not seen in 0.40.

The text was updated successfully, but these errors were encountered:

vinniefalco · 2017-02-22T20:40:44Z

How big do you expect the returned data-set to be? in megabytes?

donovanhide · 2017-02-22T20:41:31Z

Changing this timeout to 30 from 3 seems to fix the issue:
https://github.com/ripple/rippled/blob/209fe8f7a92a74b173f2b23ae263c4885fc5b16d/src/ripple/server/impl/BaseWSPeer.h#L368
I'm connecting locally, so I guess I'm not processing both the streamed data and the ledger_data responses within 3 seconds in all cases.

vinniefalco · 2017-02-22T21:03:21Z

Hmm...that look sketchy! I will investigate

vinniefalco · 2017-02-22T22:50:34Z

We're going to make a change so that the 3 second timeout will only happen during unit tests. Websocket connections from the loopback address will be 30 seconds.

donovanhide · 2017-02-23T01:08:27Z

Sounds good to me.

donovanhide · 2017-02-23T19:04:14Z

Looks like the same issue crops up more sporadically, one or two times a day:

2017-Feb-23 18:58:50 Server:TRC #23277 destroyed: 1 request
2017-Feb-23 18:58:58 Server:TRC #23278 accept:    138.197.193.51
2017-Feb-23 18:58:58 Server:TRC #23278 destroyed: 1 request
2017-Feb-23 18:59:00 Server:TRC #23279 accept:    178.19.226.15
2017-Feb-23 18:59:01 Server:TRC #23279 destroyed: 1 request
2017-Feb-23 18:59:02 Server:TRC #23280 accept:    52.25.10.5
2017-Feb-23 18:59:03 Server:TRC #23280 destroyed: 1 request
2017-Feb-23 18:59:15 Server:TRC ##8 timer: Connection timed out
2017-Feb-23 18:59:15 Server:TRC ##9 read: End of file
2017-Feb-23 18:59:23 Server:TRC #23281 accept:    96.127.136.18
2017-Feb-23 18:59:23 Server:TRC #23281 destroyed: 1 request
2017-Feb-23 18:59:25 Server:TRC #23282 accept:    52.25.10.5
2017-Feb-23 18:59:25 Server:TRC #23282 destroyed: 1 request
2017-Feb-23 18:59:41 Server:TRC #23283 accept:    178.19.226.15
2017-Feb-23 18:59:41 Server:TRC #23283 destroyed: 1 request

##8 and ##9 refer to my connection.

vinniefalco · 2017-02-23T19:18:39Z

Is it because you are requesting data that takes more than 30 seconds? Try changing the timeout to 5 minutes?

donovanhide · 2017-02-23T19:26:45Z

After the first 10 or 15 seconds at startup, I've done all the ledger_data requests I'll ever do. After that it's just reading the transaction and ledger streams and the occasional submit. When the timeout gets logged, no API call was in progress.

vinniefalco · 2017-02-23T19:32:52Z

So could this be that... it actually timed out due to inactivity?

donovanhide · 2017-02-23T19:43:43Z

Well, my code got disconnected last time around ledger 27881937. Doesn't seem like there was any large gaps between ledgers around that time, so the stream data should have been been resetting the timeout I assume.
I use a separate connection for submitting trades however. Maybe that one is timing out? Where is the timeout set between API requests? Looks like the timeout might be roughly an hour after the last submit on that second connection. Not sure an inactivity timeout is great for a bot when markets go quiet :-)

vinniefalco · 2017-02-23T19:51:02Z

If a client goes idle, rippled should issue a websocket ping every so often to keep the connection alive. We are looking into it. Probably a bug in the server.

vinniefalco · 2017-02-25T00:00:11Z

Try giving this a spin? https://github.com/vinniefalco/rippled/tree/0.50.3

Thanks

donovanhide · 2017-02-25T00:21:26Z

/usr/bin/g++ -o build/gcc.release/src/ripple/unity/app_main.o -c -Wall -frtti -std=c++14 -Wno-invalid-offsetof -pthread -Wno-sign-compare -Wno-char-subscripts -Wno-format -g -Wno-unused-but-set-variable -Wno-deprecated -O3 -fno-strict-aliasing -Wno-unuse
d-local-typedefs -DOPENSSL_NO_SSL2 -DDEPRECATED_IN_MAC_OS_X_VERSION_10_7_AND_LATER -DHAVE_USLEEP=1 -DSOCI_CXX_C11=1 -D_SILENCE_STDEXT_HASH_DEPRECATION_WARNINGS -DBOOST_NO_AUTO_PTR -DBOOST_COROUTINE_NO_DEPRECATION_WARNING -DBOOST_COROUTINES_NO_DEPRECATION
_WARNING -DNDEBUG -D_FILE_OFFSET_BITS=64 -Isrc -Isrc/beast -Isrc/beast/include -Isrc/beast/extras -Isrc/nudb/include -Ibuild/proto -Isrc/soci/src -Isrc/soci/include src/ripple/unity/app_main.cpp
In file included from src/ripple/server/impl/PlainWSPeer.h:23:0,
                 from src/ripple/server/impl/PlainHTTPPeer.h:24,
                 from src/ripple/server/impl/Door.h:26,
                 from src/ripple/server/impl/ServerImpl.h:25,
                 from src/ripple/server/Server.h:24,
                 from src/ripple/rpc/impl/ServerHandlerImp.h:25,
                 from src/ripple/rpc/ServerHandler.h:29,
                 from src/ripple/overlay/make_Overlay.h:23,
                 from src/ripple/app/main/Application.cpp:65,
                 from src/ripple/unity/app_main.cpp:24:
src/ripple/server/impl/BaseWSPeer.h: In member function ‘void ripple::BaseWSPeer<Handler, Impl>::start_timer()’:
src/ripple/server/impl/BaseWSPeer.h:436:13: error: ‘remote_address_’ was not declared in this scope
             remote_address_.address().is_loopback() ?
             ^
scons: *** [build/gcc.release/src/ripple/unity/app_main.o] Error 1
scons: building terminated because of errors.

vinniefalco · 2017-02-25T00:53:56Z

Sorry about that, Visual Studio strikes again. I've fixed the error (hopefully) waiting on Travis now. The branch has been rewritten.

donovanhide · 2017-02-25T01:37:36Z

Seems to close the connection even more aggressively now (both connections with in around 5 seconds) . Can you replicate my original issue at your end using 0.50.2?

vinniefalco · 2017-02-25T01:46:35Z

I know this one works
https://github.com/vinniefalco/rippled/commits/develop

vinniefalco · 2017-02-25T01:50:17Z

This one also works, tested it using a browser script. It stays connected even when idle
https://github.com/vinniefalco/rippled/tree/0.50.3

I am not sure what your issue is. It might be something other than an idle timeout.

donovanhide · 2017-02-25T01:57:45Z

I tried your 0.50.3 tag and it disconnected more quickly as described. Not sure a browser implementation of a websockets client is going to cover all bases. In my bot, using Go, I'm also pinging every 60 seconds:

https://github.com/rubblelabs/ripple/blob/master/websockets/remote.go#L552-L558

This is a regression as 0.40 could keep running for weeks/months at a time :-) If you need a Go repro I can knock one together tomorrow, but you'd have to install Go to build it.

vinniefalco · 2017-02-25T12:05:34Z

Well 0.40.0 used websocketpp while 0.50.0 uses Beast. Its not surprising that there's a bug. We'll figure it out!

sublimator · 2017-02-25T12:17:25Z

Dat's da moonshine!

vinniefalco · 2017-02-25T12:31:34Z

@donovanhide is your Go websocket client responding to pings (I see that it sends them but does it also reply)? rippled will not reset its timer just because it hears a ping. It only resets the timer if it gets a pong in response to a sent ping.

donovanhide · 2017-02-25T12:46:29Z

Default behaviour is to reply to all pings with a pong:

https://godoc.org/github.com/gorilla/websocket#hdr-Control_Messages
https://github.com/gorilla/websocket/blob/master/conn.go#L1041-L1054

I'll try and get a barebones repro built.

vinniefalco · 2017-02-27T17:19:59Z

See #2032

donovanhide · 2017-03-16T23:42:02Z

Is this fix not going to be in 0.60?

vinniefalco · 2017-03-17T00:34:07Z

There were two versions of the fix. A good one, and a great one. The great one includes improvements to Beast that allow concurrent ping and write operations. Its being sorted out so it can go into some version.

nbougalis · 2017-03-17T00:39:14Z

The fix Vinnie describes will go into 0.70.0.

donovanhide · 2017-03-24T14:24:01Z

I'm still getting intermittent disconnections with 0.70.0. This sounds like other people experiencing the same:

https://www.xrpchat.com/topic/3341-websocket-closing-ripple-lib

bachase · 2017-03-24T15:07:25Z

@donovanhide Were you testing with 0.70.0-b2? The fix should be 15f969a.

donovanhide · 2017-03-24T15:08:52Z

Yep, can't paste in the git log, but that's the exact commit I'm using. Gaps are longer between disconnections, but still occurs.

miguelportilla · 2017-03-31T17:12:32Z

"closing slow client" means the Websocket write queue filled up. Writing to the socket outperformed sending. We currently impose a limit of 100 queue items before considering the client too slow and disconnecting.

donovanhide · 2017-03-31T17:13:33Z

Seems a bit aggressive if the plan is to process 1000 tx/sec :-)

vinniefalco · 2017-03-31T17:16:31Z

@donovanhide I agree, something ain't right there. The server implementation needs to be redesigned anyway. But in this case i think you are really too slow, it means that the other end is not reading the data fast enough. You should be able to read on your end fast enough to keep the queue empty.

donovanhide · 2017-03-31T17:18:47Z

My code has been happily running for over two years, so not sure I want to optimise it because rippled changed its websocket library.

miguelportilla · 2017-03-31T17:19:08Z

@donovanhide That is the limit of a single Websocket write queue. It's unusual for a queue to get beyond a few items in my experience. I can work with you to figure out why it happened.

@vinniefalco Another possibility is the server upstream bandwidth was momentarily saturated.

vinniefalco · 2017-03-31T17:20:03Z

If rippled queues more than 100 items at a time, it would cause that problem.

@donovanhide Are you running your own server? You could increase the queue limit to 10,000 or remove it completely as a test.

donovanhide · 2017-03-31T17:22:26Z

Sounds like it should be a configurable. My code is the only client of that server. I need to add each item of metaData that I receive into my version of the ledger state. I could buffer them all and then process them, but seems like quite a lot of work because the number 100 was hard-coded.

vinniefalco · 2017-03-31T17:23:30Z

@donovanhide How do you prevent a memory exhaustion attack where someone subscribes to a million streams and then reads only one byte at a time per second on the connection?

donovanhide · 2017-03-31T17:23:51Z

Here's a typical snapshot of my time budget for each ledger:

Receiving 91.583198ms Bellman: 148.022203ms Signing: 688.565µs Submitting: 16.415657ms

donovanhide · 2017-03-31T17:24:41Z

In that situation, you leave the send queue limit to a low value. For private servers, it's not an issue.

donovanhide · 2017-03-31T17:25:26Z

Or you put an nginx websocket proxy in front of it and configure the rate limiter :-)

vinniefalco · 2017-03-31T17:28:58Z

Or you put an nginx websocket proxy in front of it and configure the rate limiter :-)

Oh I like that much better

miguelportilla · 2017-03-31T17:30:20Z

@donovanhide Can you please try a large queue limit size to see if it eliminates the problem? It might be a good idea to also log the max size the queue grows to.

donovanhide · 2017-03-31T17:33:24Z

Just to be clear, a rate-limited nginx websocket proxy is a solution to attack prevention, not my slow transaction stream message reading problem :-)
@miguelportilla Yep, I'll whack it up. If you want to reproduce, you could replay that ledger with a timed sleep between each message read. If the transaction per ledger volume goes up though, it's more likely that others will hit this with their javascript code.

miguelportilla · 2017-03-31T17:43:05Z

@donovanhide Thank you. I will replay that ledger and reproduce on my end. What does your RPC subscription look like?

donovanhide · 2017-03-31T17:44:17Z

@miguelportilla

{
        "command" : "subscribe",
        "id" : 1,
        "streams" : [ "ledger", "transactions", "server" ]
}

donovanhide · 2017-03-31T17:55:57Z

Actually just reviewed my code (it's been a while...) and seen that I am buffering all received messages in the transaction stream for a ledger before processing them, which suggests that the typical time of around 70ms to receive a typical ledger is not down to what my code is doing, as far as I can see.

Would be interesting to see how long it takes for you to receive a full ledger's worth of transactions. That is, examine TxCount in the ledger message, start timer, receive TxCount transaction messages, stop timer. Ledger 28,696,629 was another biggie :-)

vinniefalco · 2017-03-31T18:27:26Z

Just to be clear, a rate-limited nginx websocket proxy is a solution to attack prevention, not my slow transaction stream message reading problem :-)

Yes, I get that. I would rather rippled focus on what it does best, implementing RCL, and offload security solutions to other products that specialize in it. I don't think rippled can compete with nginx when it comes to offering versatility for managing network resources (nor would I want it to).

tuloski · 2017-04-10T16:31:47Z

Now it seems stable. My bots lost around 100k XRP...but fine...maybe I should stop this "business" :)

tuloski · 2017-04-10T20:15:27Z

Mmmm...it is not true...it is not stable.
Got 5 disconnections in 6 hours :(

miguelportilla · 2017-04-10T20:39:27Z

@tuloski Are you using you running rippled? If so, which version and what is it hosted on?

tuloski · 2017-04-10T23:23:03Z

No I'm using Ripple's public servers.

miguelportilla · 2017-04-10T23:51:23Z

What does your RPC subscription look like?

tuloski · 2017-04-11T09:19:20Z

I'm using Ripple-lib...

miguelportilla · 2017-04-11T12:45:00Z

@tuloski I would like to figure why you are getting disconnected. Would you please share with me the relevant sections of your JS script so that I may use them to debug on my end? I can be reached at miguel at ripple dot com

tuloski · 2017-04-11T14:44:10Z

Well it's Ripple-lib 0.12.6: https://github.com/ripple/ripple-lib/tree/0.12.6

tuloski · 2017-04-20T12:20:17Z

This is what I'm getting:
/home/odroid/node_modules/ripple-lib/node_modules/ws/lib/WebSocket.js:214
else throw new Error('not opened');
^

Error: not opened
at WebSocket.send (/home/odroid/node_modules/ripple-lib/node_modules/ws/lib/WebSocket.js:214:16)
at Server._sendMessage (/home/odroid/node_modules/ripple-lib/dist/npm/server.js:746:14)

The servers I'm connected are: wss://s1.ripple.com:443, wss://s-west.ripple.com:443

miguelportilla · 2017-04-20T19:58:50Z

@tuloski What error message or code do you receive when you are disconnected?

tuloski · 2017-04-20T20:29:11Z

I don't know...it doesn't report the error.
And I don't know how to modify the code to show me the error...all that js drives me crazy.

donovanhide mentioned this issue Mar 24, 2017

Websocket closing XRPLF/xrpl.js#749

Closed

nbougalis closed this as completed in 8b43d67 Apr 1, 2017

Websocket timeout issues #2026

Websocket timeout issues #2026

Comments

donovanhide commented Feb 22, 2017

vinniefalco commented Feb 22, 2017

donovanhide commented Feb 22, 2017

vinniefalco commented Feb 22, 2017

vinniefalco commented Feb 22, 2017

donovanhide commented Feb 23, 2017

donovanhide commented Feb 23, 2017

vinniefalco commented Feb 23, 2017

donovanhide commented Feb 23, 2017

vinniefalco commented Feb 23, 2017

donovanhide commented Feb 23, 2017

vinniefalco commented Feb 23, 2017

vinniefalco commented Feb 25, 2017

donovanhide commented Feb 25, 2017

vinniefalco commented Feb 25, 2017

donovanhide commented Feb 25, 2017

vinniefalco commented Feb 25, 2017

vinniefalco commented Feb 25, 2017

donovanhide commented Feb 25, 2017

vinniefalco commented Feb 25, 2017

sublimator commented Feb 25, 2017 via email

vinniefalco commented Feb 25, 2017

donovanhide commented Feb 25, 2017

vinniefalco commented Feb 27, 2017

donovanhide commented Mar 16, 2017

vinniefalco commented Mar 17, 2017

nbougalis commented Mar 17, 2017

donovanhide commented Mar 24, 2017 • edited Loading

bachase commented Mar 24, 2017

donovanhide commented Mar 24, 2017 • edited Loading

miguelportilla commented Mar 31, 2017 • edited Loading

donovanhide commented Mar 31, 2017

vinniefalco commented Mar 31, 2017

donovanhide commented Mar 31, 2017

miguelportilla commented Mar 31, 2017 • edited Loading

vinniefalco commented Mar 31, 2017 • edited Loading

donovanhide commented Mar 31, 2017

vinniefalco commented Mar 31, 2017 • edited Loading

donovanhide commented Mar 31, 2017

donovanhide commented Mar 31, 2017

donovanhide commented Mar 31, 2017

vinniefalco commented Mar 31, 2017

miguelportilla commented Mar 31, 2017

donovanhide commented Mar 31, 2017

miguelportilla commented Mar 31, 2017

donovanhide commented Mar 31, 2017 • edited Loading

donovanhide commented Mar 31, 2017

vinniefalco commented Mar 31, 2017

tuloski commented Apr 10, 2017

tuloski commented Apr 10, 2017

miguelportilla commented Apr 10, 2017

tuloski commented Apr 10, 2017

miguelportilla commented Apr 10, 2017

tuloski commented Apr 11, 2017

miguelportilla commented Apr 11, 2017 • edited Loading

tuloski commented Apr 11, 2017

tuloski commented Apr 20, 2017

miguelportilla commented Apr 20, 2017

tuloski commented Apr 20, 2017

donovanhide commented Mar 24, 2017 •

edited

Loading

donovanhide commented Mar 24, 2017 •

edited

Loading

miguelportilla commented Mar 31, 2017 •

edited

Loading

miguelportilla commented Mar 31, 2017 •

edited

Loading

vinniefalco commented Mar 31, 2017 •

edited

Loading

vinniefalco commented Mar 31, 2017 •

edited

Loading

donovanhide commented Mar 31, 2017 •

edited

Loading

miguelportilla commented Apr 11, 2017 •

edited

Loading