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

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

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