No response on query received

[FlashPlayer13]

Hi,

I'm still facing this type of problem: https://github.com/JKorf/Bitfinex.Net/issues/99. For some reason order canceling operation may return "No response on query received" after 10 seconds of waiting. Also when (right after) this happens - looks like there is some kind of auto socket restart, because all orderbooks resend full state, like if i subscribed on them first time. Also when this happens, if i have some orders on fly to server, it can stuck on socketClient.CancelOrder method without any return forever. So lot of strange things happenning.

I am working with last available version.

[JKorf]

Hi, I'd like to help you but you'll have to provide some more data. First off; you say cancellation MAY return "no response". So it only happens occasionally? How often? You also say all orderbooks resend full state. What order book are those? You mean the subscriptions you have on the same socket client?

Can you maybe enable debug logging and share the logging with me when you're experience the issues? Debug logging can be enabled by using

 new BitfinexSocketClient(new Bitfinex.Net.Objects.BitfinexSocketClientOptions() {
                LogVerbosity = LogVerbosity.Debug
});

[FlashPlayer13]

Hi. Glad you are here!) I'm facing this problem not often but i can't somehow prevent it. For some reason client stops updating anything and after 10 seconds just returns to work again like i started it from scratch. I can track this because i'm logging all what is dropping here: _socketClient.SubscribeToBookUpdates. And after this type of restart i see that any ticker i was subscribed resends whole orderbook. Before this 10 seconds blackout every time i receive this message in responce on order operation (it can be order cancel, or place order operation): "No response on query received". So my log looks like:

• Everything ok
• No response on query received message
• 10 seconds of silence
• All orderbooks resend me whole state
• Everything ok

And there can be also a situation - if i make any order operation within this 10 seconds (_socketClient.PlaceOrder or _socketClient.CancelOrder) - it will never response anything. So it get stuck on this line of code.

I will enable debug logging and wait for problem repeat.

[FlashPlayer13]

Btw all i need is just set LogVerbosity? Where client will write logs by default?

[JKorf]

It sounds like there is a hickup in the connection. How stable is your internet connection? By default the log will be written using Debug.WriteLine, so it will appear in your editor output. You can set the logger output by adding textwriter implementation to the LogWriters option:

var tw = File.OpenWrite("C:/text.log");
            var writer = new StreamWriter(tw);
            var socketClient = new BitfinexSocketClient(new Bitfinex.Net.Objects.BitfinexSocketClientOptions()
            {
                LogVerbosity = LogVerbosity.Debug,
                LogWriters = new List<TextWriter>{
                    writer
                }
            });

[FlashPlayer13]

Yes, that's a problem that connection is stable. I'm pinging bifinex in cycle and no problems. I will setup logging this way - will it catch hickup if it is realy it?

[JKorf]

Yes, debug logging will show if a connection is closed and the reconnection process, as well as all messages send/received.

[FlashPlayer13]

Hi, i wrote this comment in another issue, but maybe i should update my own.

I logged few days in debug mode and finally catch a problem that maybe somehow related to this issue: at some point bid becomes more than ask. Last month i am facing this problems time to time: loosing connection and "No responce on query" and bid > ask situation. There was no such problems before, so i guess they are connected.

I will paste a part of log here, that clearly shows problem:

2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9033.5,0,1]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9031,0,1]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9030.1,0,1]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9023.9,0,1]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9022.4,0,1]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9036.4,0,-1]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9034.4,1,0.0878857]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9033.8,1,1]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9033.6,1,-0.05]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9031.1,2,0.65358673]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9030.4,1,0.2]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9023.8,3,1.2525]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9022.2,2,1.1977]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9034.5,5,-4.88206193]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9040.2,2,-0.77477942]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9040.9,1,-0.85]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9042.4,1,-0.0008]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [7,"tu",[412495852,1580195912669,-0.1321143,9034.4]] 2020.01.28 10:18:32:781 | Debug | Socket 1 received data: [560884,[9030.4,0,1]] 2020.01.28 10:18:32:781 | Debug | Socket 1 received data: [560884,[9023.3,0,1]] 2020.01.28 10:18:32:781 | Debug | Socket 1 received data: [560884,[9036.5,0,-1]] 2020.01.28 10:18:32:781 | Debug | Socket 1 received data: [560884,[9030.5,1,0.2]] 2020.01.28 10:18:32:781 | Debug | Socket 1 received data: [560884,[9022,1,0.0663]] 2020.01.28 10:18:32:781 | Debug | Socket 1 received data: [560884,[9034.5,4,-3.3662898]] 2020.01.28 10:18:32:781 | Debug | Socket 1 received data: [560884,[9040.2,1,-0.0008]] 2020.01.28 10:18:32:781 | Debug | Socket 1 received data: [560884,[9040.4,1,-0.77397942]]

Here you can see that in this lines i got bid > ask:

2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9034.4,1,0.0878857]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9033.8,1,1]] 2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [560884,[9033.6,1,-0.05]]

Bid = 9034.4 and Ask = 9033.6. And it will not change in few next rows. But maybe this row:

2020.01.28 10:18:32:640 | Debug | Socket 1 received data: [7,"tu",[412495852,1580195912669,-0.1321143,9034.4]]

means something we need to take a note?

[FlashPlayer13]

Finally catched initial problem. Looks like high freq placing/canceling order cycles can trigger bitfinex to close socket. But when socket is closing - it looses some info about order operation in process. For example, in this situation cancel order call will not answer forever:

2020.02.04 18:22:39:075 | Info | Going to place order 2020.02.04 18:22:39:075 | Debug | Socket 1 sending data: [0,"on",null,{"type":"LIMIT","symbol":"tETPUSD","amount":"-36.79504233","price":"0.32829","cid":3265}] 2020.02.04 18:22:39:091 | Debug | Socket 1 received data: [313098,[380.46,0,-1]] 2020.02.04 18:22:39:091 | Debug | Socket 1 received data: [313098,[380.48,0,-1]] 2020.02.04 18:22:39:091 | Debug | Socket 1 received data: [313098,[379.64,2,7.25]] 2020.02.04 18:22:39:091 | Debug | Socket 1 received data: [313098,[379.62,1,1.25]] 2020.02.04 18:22:39:091 | Debug | Socket 1 received data: [313098,[380.42,1,-1.25]] 2020.02.04 18:22:39:091 | Debug | Socket 1 received data: [313098,[380.45,1,-1.25]] 2020.02.04 18:22:39:153 | Debug | Socket 1 received data: {"event":"info","code":20051,"msg":"Stopping. Please try to reconnect"} 2020.02.04 18:22:39:153 | Debug | Info event received: { "event": "info", "code": 20051, "msg": "Stopping. Please try to reconnect" } 2020.02.04 18:22:39:153 | Info | Code 20051 received, reconnecting socket 2020.02.04 18:22:39:153 | Debug | Socket 1 closing 2020.02.04 18:22:39:169 | Debug | Socket 1 received data: [318778,[0.32829,1,-1231.26483692]] 2020.02.04 18:22:39:169 | Debug | Socket 1 received data: [0,"n",[1580829758.643,"on-req",null,null,[38825959700,null,3265,"tETPUSD",1580829758633,1580829758633,-36.79504233,-36.79504233,"LIMIT",null,null,null,0,"ACTIVE",null,null,0.32829,0,0,0,null,null,null,0,null,null,null,null,"API>BFX",null,null,null],null,"SUCCESS","Submitting limit sell order for -36.79504233 ETP."]] 2020.02.04 18:22:39:169 | Debug | Socket 1 received data: [0,"on",[38825959700,null,3265,"tETPUSD",1580829758633,1580829758645,-36.79504233,-36.79504233,"LIMIT",null,null,null,0,"ACTIVE",null,null,0.32829,0,0,0,null,null,null,0,0,null,null,null,"API>BFX",null,null,null]] 2020.02.04 18:22:39:169 | Info | Going to cancel order 38825959700 2020.02.04 18:22:39:169 | Debug | Socket 1 sending data: [0,"oc",null,{"id":38825959700}] 2020.02.04 18:22:39:185 | Debug | Socket 1 received data: [317982,[187.42,0,1]] 2020.02.04 18:22:39:185 | Debug | Socket 1 received data: [317982,[188.23,0,-1]] 2020.02.04 18:22:39:185 | Debug | Socket 1 received data: [317982,[187.73,1,3]] 2020.02.04 18:22:39:185 | Debug | Socket 1 received data: [317982,[187.99,1,-3]] 2020.02.04 18:22:39:185 | Debug | Socket 1 received data: [313098,[378.32,0,1]] 2020.02.04 18:22:39:185 | Debug | Socket 1 received data: [313098,[379.65,1,1.25]] 2020.02.04 18:22:39:185 | Debug | Socket 1 received data: [313098,[379.64,1,6]] 2020.02.04 18:22:39:247 | Debug | Socket 1 received data: [296885,[0.26607,0,1]] 2020.02.04 18:22:39:247 | Debug | Socket 1 received data: [296885,[0.26785,0,-1]] 2020.02.04 18:22:39:247 | Debug | Socket 1 received data: [296885,[0.26787,0,-1]] 2020.02.04 18:22:39:247 | Debug | Socket 1 received data: [296885,[0.26645,2,10400]] 2020.02.04 18:22:39:247 | Debug | Socket 1 received data: [296885,[0.26621,1,651.43775808]] 2020.02.04 18:22:39:247 | Debug | Socket 1 received data: [296885,[0.26615,2,1377.86333063]] 2020.02.04 18:22:39:247 | Debug | Socket 1 received data: [296885,[0.2675,1,-1302.87551615]] 2020.02.04 18:22:39:247 | Debug | Socket 1 received data: [296885,[0.26782,1,-23627.7717]] 2020.02.04 18:22:39:263 | Info | Socket 1 Connection lost, will try to reconnect after 00:00:05 2020.02.04 18:22:39:263 | Debug | Socket 1 closed 2020.02.04 18:22:44:277 | Debug | Socket 1 resetting 2020.02.04 18:22:44:277 | Debug | Socket 1 connecting 2020.02.04 18:22:44:387 | Debug | Socket 1 connected

[JKorf]

Hi thanks for the updates, these logs help a lot. So it seems that we got a reconnect request from the server, but we still send a cancel order request which doesn't get processed. I'll do some work to fix this.

On the order book issue, I'll still have to do some digging as I haven't yet figured out that issue.

[JKorf]

I've pushed a fix for the operation being lost when reconnecting, can you try the new version and see if it fixed your issues?

[FlashPlayer13]

Hi, thank you for a fix. I will check it now. I am not sure i will be able to trigger reconnect request from server, but when it will happen - i will check if all become smooth. Problem with orderbook is strange and annoying - without any reason bid becomes more than ask. I will also log further for more situations here and will post updates in this issue.

[FlashPlayer13]

Hi. This issue looks like solved, but problem with bid/ask still exists. Do we need to close this issue and open new, or continue here? Also is there any option to hard socket reconnect (reset). This will be some type of workaround on issue with bid/ask (reset everything and receive fresh full orderbooks)

[FlashPlayer13]

Hi again) I got this error "No response on query received" again after update. But have no related logs. Actually there is a strange problem with logs too. They stop writing suddenly without any reason, so just after some time log file will never update.