Re: [Quickfixj-users] Issues with Heartbeat When Connecting via HTTP Proxy

[Florian L. <fl...@un...>]

I assumed as much as well in the beginning, but I ruled this out since 
it doesn't happen with the same message volume but without a proxy in 
between, and it also doesn't happen with the proxy but the heartbeat 
interval configured as 100'000s, and lastly it also immediately stops 
when sending out the heartbeat (and not after some timeout because the 
heartbeat arrives too late at the other side and they close the 
connection because of it). There was never a time during testing where 
any incoming message was processed after such a sent heartbeat and only 
then the disconnect happened, the heartbeat message was always the last 
thing logged.

The really weird part about for me is that there is absolutely no kind 
of error thrown or anything. So it seems Quickfix/j still believes 
everything is fine even though the connection is broken...

On 07.12.2020 15:37, Colin DuPlantis wrote:
> QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
> QuickFIX/J Support: http://www.quickfixj.org/support/
>
>
>
> Apologies if this has been asked and answered, but, is it possible the 
> issue is related to your Application becoming overwhelmed with 
> incoming messages and not sending out the heartbeat because it takes 
> too long to respond to the incoming messages?
>
> I ask this because you say that it breaks "where the is lots of 
> incoming traffic".
>
> One way to test this would be to have your receiver either not process 
> incoming messages or stick them in an adjacent thread to process, thus 
> freeing up the QFJ Application thread.
>
> On 12/7/20 6:34 AM, Florian Leu wrote:
>> QuickFIX/J Documentation:http://www.quickfixj.org/documentation/
>> QuickFIX/J Support:http://www.quickfixj.org/support/
>>
>>
>>
>> Hi Chris
>>
>> Sorry for the late reply and thanks for taking an interest in this issue.
>>
>> The connection doesn't break in quiet times, but in times where there 
>> is lots of incoming traffic, while at the same time I try to send out 
>> a heartbeat message after the configured interval. Since I'm only a 
>> message receiver, I never send out my own application messages and 
>> therefore Quickfix/j produces the heartbeat messages regularly. But 
>> somehow sending out a (heartbeat) messages via proxy while 
>> simultaneously receiving incoming (application) messages seems to 
>> break the connection. I verified with the counter party that they 
>> never receive my heartbeat in such a case and I stop receiving their 
>> messages as well. This behavior doesn't happen when we connect 
>> directly without proxy, but it happens with the proxy in my 
>> development environment as well as with the proxy at the client's 
>> production environment (where a direct connection is not possible).
>>
>> The end of the log basically looks like this:
>>
>> 2020-11-25 17:12:24.448  INFO 19036 --- [ssage Processor] 
>> c.u.fix_adapter.fix.FixApp    : fromApp: 
>> 8=FIXT.1.1
9=312
35=6
34=8191
43=Y
49=<REPLACED>
52=20201125-16:12:14.781
56=<REPLACED>
115=<REPLACED>
122=20201125-07:00:10.209
142=MADRID
15=EUR
22=4
23=Tag23-7201
27=25000000
28=N
44=97.782
48=ES0370152003
54=2
55=ALRSRU 
>> 0 
>> 01/11/2020
60=20201125-07:00:07.103
235=MATURITY
854=0
199=1
104=E
2529=1
2530=3
2531=-126.2
2532=3
10=136

>> 2020-11-25 17:12:24.448  INFO 19036 --- [ssage Processor] 
>> c.u.fix_adapter.fix.FixApp    : fromApp: 
>> 8=FIXT.1.1
9=327
35=6
34=8192
43=Y
49=<REPLACED>
52=20201125-16:12:14.781
56=<REPLACED>
115=<REPLACED>
122=20201125-07:00:10.210
142=MADRID
15=EUR
22=4
23=Tag23-7202
27=2200000
28=N
44=98.452
48=ES0361796016
54=2
55=ALRSRU 
>> 0 
>> 01/11/2020
60=20201125-07:00:07.103
235=MATURITY
236=0.058488653
854=0
199=1
104=E
2529=1
2530=3
2531=-130.3
2532=3
10=116

>> 2020-11-25 17:12:24.448  INFO 19036 --- [ssage Processor] 
>> c.u.fix_adapter.fix.FixApp    : fromApp: 
>> 8=FIXT.1.1
9=327
35=6
34=8193
43=Y
49=<REPLACED>
52=20201125-16:12:14.781
56=<REPLACED>
115=<REPLACED>
122=20201125-07:00:10.211
142=MADRID
15=EUR
22=4
23=Tag23-7203
27=5000000
28=N
44=100.15
48=ES0305248009
54=2
55=ALRSRU 
>> 0 
>> 01/11/2020
60=20201125-07:00:07.103
235=MATURITY
236=0.124030151
854=0
199=1
104=E
2529=1
2530=3
2531=-124.8
2532=1
10=067

>> 2020-11-25 17:12:24.456  INFO 19036 --- [ssage Processor] 
>> c.u.fix_adapter.fix.FixApp    : fromApp: 
>> 8=FIXT.1.1
9=327
35=6
34=8194
43=Y
49=<REPLACED>
52=20201125-16:12:14.781
56=<REPLACED>
115=<REPLACED>
122=20201125-07:00:10.211
142=MADRID
15=EUR
22=4
23=Tag23-7204
27=5500000
28=N
44=99.752
48=ES0370151021
54=2
55=ALRSRU 
>> 0 
>> 01/11/2020
60=20201125-07:00:07.103
235=MATURITY
236=0.013007278
854=0
199=1
104=E
2529=1
2530=3
2531=-126.5
2532=3
10=100

>> 2020-11-25 17:12:24.456  INFO 19036 --- [ssage Processor] 
>> c.u.fix_adapter.fix.FixApp    : fromApp: 
>> 8=FIXT.1.1
9=326
35=6
34=8195
43=Y
49=<REPLACED>
52=20201125-16:12:14.781
56=<REPLACED>
115=<REPLACED>
122=20201125-07:00:10.213
142=MADRID
15=EUR
22=4
23=Tag23-7205
27=600000
28=N
44=96.997
48=ES0377984002
54=2
55=ALRSRU 
>> 0 
>> 01/11/2020
60=20201125-07:00:07.103
235=MATURITY
236=0.103649457
854=0
199=1
104=E
2529=1
2530=3
2531=-126.8
2532=3
10=093

>> 2020-11-25 17:12:24.456  INFO 19036 --- [ssage Processor] 
>> c.u.fix_adapter.fix.FixApp    : fromApp: 
>> 8=FIXT.1.1
9=312
35=6
34=8196
43=Y
49=<REPLACED>
52=20201125-16:12:14.781
56=<REPLACED>
115=<REPLACED>
122=20201125-07:00:10.213
142=MADRID
15=EUR
22=4
23=Tag23-7206
27=25000000
28=N
44=99.681
48=ES0377988003
54=2
55=ALRSRU 
>> 0 
>> 01/11/2020
60=20201125-07:00:07.103
235=MATURITY
854=0
199=1
104=E
2529=1
2530=3
2531=-124.1
2532=3
10=162

>> 2020-11-25 17:12:24.456  INFO 19036 --- [ssage Processor] 
>> c.u.fix_adapter.fix.FixApp    : fromApp: 
>> 8=FIXT.1.1
9=358
35=6
34=8197
43=Y
49=<REPLACED>
52=20201125-16:12:14.781
56=<REPLACED>
115=<REPLACED>
122=20201125-07:00:10.213
142=MADRID
15=EUR
22=4
23=Tag23-7207
27=2000000
28=N
44=98.914
48=XS1057659838
54=2
55=ALRSRU 
>> 0 
>> 01/11/2020
60=20201125-07:00:07.103
218=0.31
235=MATURITY
236=3.895172789
699=XS1057659838
761=4
854=0
199=1
104=E
2529=1
2530=3
2531=332.9
2532=1
10=221

>> 2020-11-25 17:12:24.456  INFO 19036 --- [ssage Processor] 
>> c.u.fix_adapter.fix.FixApp    : fromApp: 
>> 8=FIXT.1.1
9=357
35=6
34=8198
43=Y
49=<REPLACED>
52=20201125-16:12:14.781
56=<REPLACED>
115=<REPLACED>
122=20201125-07:00:10.213
142=MADRID
15=EUR
22=4
23=Tag23-7208
27=8700000
28=N
44=104.817
48=ES0314970239
54=2
55=ALRSRU 
>> 0 
>> 01/11/2020
60=20201125-07:00:07.103
218=93.0
235=MATURITY
236=0.04773846
699=DE0001141687
761=4
854=0
199=1
104=E
2529=1
2530=3
2531=20.3
2532=3
10=064

>> 2020-11-25 17:12:24.456  INFO 19036 --- [ssage Processor] 
>> c.u.fix_adapter.fix.FixApp    : fromApp: 
>> 8=FIXT.1.1
9=346
35=6
34=8199
43=Y
49=<REPLACED>
52=20201125-16:12:14.781
56=<REPLACED>
115=<REPLACED>
122=20201125-07:00:10.213
142=MADRID
15=EUR
22=4
23=Tag23-7209
27=1185264
28=N
44=103.593
48=EU000A1U9829
54=2
55=ALUFP 
>> 6.45 
>> 03/15/2029
60=20201125-07:00:07.103
218=30.48
235=MATURITY
699=DE0001141703
761=4
854=0
199=1
104=E
2529=1
2530=3
2531=-42.3
2532=3
10=065

>> 2020-11-25 17:12:24.480  INFO 19036 --- [ssage Processor] 
>> c.u.fix_adapter.fix.FixApp    : toAdmin: 
>> 8=FIXT.1.1
9=66
35=0
34=50
49=<REPLACED>
52=20201125-16:12:24.480
56=<REPLACED>
10=191

>> 2020-11-25 17:12:24.622  INFO 19036 --- [   scheduling-1] 
>> c.unitek.fix_adapter.ScheduledTasks  : Saved [400] IOI messages.
>>
>> I get 1000s of incoming messages that I printed out for debugging 
>> purposes as "fromApp" log statements....and then there is the first 
>> heartbeat that I send out, logged as "toAdmin", after the configured 
>> interval (e.g. 30s after logging on). After that the incoming 
>> messages immediately stop, as if the outgoing heartbeat message 
>> caused a disconnect of the connection, but in a way that Quickfix/j 
>> doesn't even realize that something is wrong because no "recover 
>> attempt" is done which I usually see when the counter party is e.g. 
>> really offline for a time, then Quickfix/j usually tries to reconnect 
>> until the connection can be re-established. But in case of this 
>> proxy-disconnect, the application is then in a state that Quickfix/j 
>> seems not to be able to get out of again. But if I send out a 
>> heartbeat message in a time where there are no incoming messages 
>> simultaneously, then the heartbeat goes through just fine and doesn't 
>> cause a disconnect, so only when both incoming and outgoing messages 
>> occur together, this seems to be an issue, as if the proxy were a 
>> one-way-street that shuts down if there is traffic from both sides at 
>> the same time.
>>
>> The proxy settings used in my test environment initiator.cfg file are 
>> as follows:
>>
>> ProxyHost=194.191.110.6 ProxyPassword=test ProxyPort=3128 
>> ProxyType=http ProxyUser=test ProxyVersion=1.1
>>
>> There are also config parameters ProxyDomain and ProxyWorkstation 
>> available in Quickfix/j, but I didn't find out what they are used for.
>>
>> I implemented my own workaround now be initiating a logout/logon 
>> after not receiving an incoming message for 3 minutes, but that only 
>> works because we know that we basically get a constant stream of 
>> messages, so when we receive nothing for 3 minutes something must be 
>> wrong, but that's more a workaround then a solution, same as setting 
>> heartbeat interval to 100'000 to avoid getting into this situation in 
>> the first place.
>>
>> Regards, Florian
>>
>> PS: The newer answer in this mail-thread from Andrew Marlow seems to 
>> belong to another topic altogether...
>>
>>
>> On 02.12.2020 15:28, Christoph John wrote:
>>> Hi,
>>>
>>> can you share some message and event logs?
>>> Are you saying that the connection only breaks when a Heartbeat 
>>> *needs* to be sent, i.e. when there is always traffic the connection 
>>> works, but in quiet times the connection will break?
>>>
>>> Cheers,
>>> Chris.
>>>
>>>
>>> On 24.11.20 09:57, Florian Leu wrote:
>>>> QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
>>>> QuickFIX/J Support: http://www.quickfixj.org/support/
>>>>
>>>>
>>>> Hi everyone
>>>>
>>>> I have a weird issue that my quickfix initiator works fine when 
>>>> connecting directly to the message supplier, but as soon as we 
>>>> connect via an HTTP proxy, it works for the first n seconds and 
>>>> then the messages stop arriving.
>>>>
>>>> I've now managed to trace the problem to the fact that those n 
>>>> seconds are exactly what is configured for the heartbeat interval, 
>>>> i.e. if I set this heartbeat interval higher, then it works longer 
>>>> and if I set it e.g. to 5, then it already stops after 5 seconds.
>>>>
>>>> At first I assumed the counter-party just closes the connection if 
>>>> they don't receive the heartbeat on time, but then I learned that 
>>>> after a missing heartbeat message first a test request is sent out 
>>>> and only after that a connection would be closed. So it seems to me 
>>>> that actually the sending out of the heartbeat from the Quickfix/j 
>>>> library (version 2.2.0) via proxy somehow seems to block the 
>>>> incoming traffic, as though the proxy was a one way street. Since 
>>>> the logon message exchange works, I know that communicating both 
>>>> ways actually works, but it seems that sending out a heartbeat 
>>>> while simultaneously processing an incoming stream of messages 
>>>> seems to somehow cut of this incoming stream for good. I can 
>>>> literally see in my logs that the incoming messages are processed 
>>>> via the fromApp method exactly up to the point that my first 
>>>> heartbeat is sent out, so logging this heartbeat via the toAdmin 
>>>> method is always the last thing logged before the communication 
>>>> stops altogether....no new incoming or outgoing messages are logged 
>>>> until the software is restarted.
>>>>
>>>> Has anyone come across a similar issue? And is there a solution for 
>>>> it? For the moment we think about just disabling the heartbeat 
>>>> messages altogether (that seems to work for now), but that it more 
>>>> of a hack workaround in my opinion and not an actual solution.
>>>>
>>>> Thanks for your support and regards,
>>>> Florian
>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> Quickfixj-users mailing list
>>>> Qui...@li...
>>>> https://lists.sourceforge.net/lists/listinfo/quickfixj-users
>>>
>>> -- 
>>> Christoph John
>>> Software Engineering
>>> T +49 241 557080-28
>>> chr...@ma...
>>>
>>> MACD GmbH
>>> Oppenhoffallee 103
>>> 52066 Aachen, Germany
>>> www.macd.com
>>>
>>> Amtsgericht Aachen: HRB 8151
>>> Ust.-Id: DE 813021663
>>> Geschäftsführer: George Macdonald
>>
>>
>> _______________________________________________
>> Quickfixj-users mailing list
>> Qui...@li...
>> https://lists.sourceforge.net/lists/listinfo/quickfixj-users
> -- 
> Colin DuPlantis
> Chief Architect, Marketcetera
> Download, Run, Trade
> 888.868.4884
> https://www.marketcetera.com
>
>
> _______________________________________________
> Quickfixj-users mailing list
> Qui...@li...
> https://lists.sourceforge.net/lists/listinfo/quickfixj-users