Not able to connect with ssl through proxy

[AndreAfonso87]

Describe the bug
We are trying to connect with SSL through Proxy, but the connection is not being made.

To Reproduce
Have set properties:
ProxyType=http
ProxyHost=XXX
ProxyPort=80

Expected behavior
SSL connection through proxy

system information:

• OS: RedHat 8.9
• Java version 17
• QFJ Version 2.3.1
• SpringBoot 2.7.18
• mina-core version: 2.1.8

Additional context
Startup logs:
. ____ _ __ _ _
/\ / ' __ _ () __ __ _ \ \ \
( ( )__ | '_ | '| | ' / ` | \ \ \
\/ )| |)| | | | | || (| | ) ) ) )
' || .__|| ||| |_, | / / / /
=========||==============|/=////
:: Spring Boot :: (v2.7.18)

{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"The following 1 profile is active: "fix-adapter-APP-current"","thread_name":"main","@timestamp":"2024-01-08T15:32:45.502+0000","level":"INFO","logger_name":"com.dummy.fix.FixAdapterRunner"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Started FixAdapterRunner in 14.723 seconds (JVM running for 19.232)","thread_name":"main","@timestamp":"2024-01-08T15:32:56.713+0000","level":"INFO","logger_name":"com.dummy.fix.FixAdapterRunner"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"IDLE State. Passive mode","thread_name":"main","@timestamp":"2024-01-08T15:32:56.727+0000","level":"INFO","logger_name":"com.dummy.fix.AppController"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"JMS Queue browsing started for queue: UK.APP.FIXADAPTER.CONTROLLER","thread_name":"main","@timestamp":"2024-01-08T15:32:56.896+0000","level":"DEBUG","logger_name":"com.dummy.fix.AppController"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Found messages: true","thread_name":"main","@timestamp":"2024-01-08T15:32:56.940+0000","level":"DEBUG","logger_name":"com.dummy.fix.AppController"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Waiting 50000 milliseconds","thread_name":"main","@timestamp":"2024-01-08T15:32:56.940+0000","level":"DEBUG","logger_name":"com.dummy.fix.AppController"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"JMS Queue browsing started for queue: UK.APP.FIXADAPTER.CONTROLLER","thread_name":"main","@timestamp":"2024-01-08T15:33:46.977+0000","level":"DEBUG","logger_name":"com.dummy.fix.AppController"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Found messages: true","thread_name":"main","@timestamp":"2024-01-08T15:33:47.010+0000","level":"DEBUG","logger_name":"com.dummy.fix.AppController"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Waiting 50000 milliseconds","thread_name":"main","@timestamp":"2024-01-08T15:33:47.011+0000","level":"DEBUG","logger_name":"com.dummy.fix.AppController"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"JMS Queue browsing started for queue: UK.APP.FIXADAPTER.CONTROLLER","thread_name":"main","@timestamp":"2024-01-08T15:34:37.042+0000","level":"DEBUG","logger_name":"com.dummy.fix.AppController"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Found messages: false","thread_name":"main","@timestamp":"2024-01-08T15:34:37.062+0000","level":"DEBUG","logger_name":"com.dummy.fix.AppController"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"I'm now in a LIVE State","thread_name":"main","@timestamp":"2024-01-08T15:34:37.063+0000","level":"INFO","logger_name":"com.dummy.fix.AppController"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"[FIXT.1.1:SANUUATFIX->RTNSFIXUAT] monday, tuesday, wednesday, thursday, friday, saturday, 03:00:00-UTC - 21:55:00-UTC (monday, tuesday, wednesday, thursday, friday, saturday, 03:00:00-GMT - 21:55:00-GMT)","thread_name":"main","@timestamp":"2024-01-08T15:34:39.695+0000","level":"INFO","logger_name":"quickfix.DefaultSessionSchedule"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Session FIXT.1.1:SANUUATFIX->RTNSFIXUAT schedule is monday, tuesday, wednesday, thursday, friday, saturday, 03:00:00-UTC - 21:55:00-UTC (monday, tuesday, wednesday, thursday, friday, saturday, 03:00:00-GMT - 21:55:00-GMT)","thread_name":"main","@timestamp":"2024-01-08T15:34:40.032+0000","level":"INFO","logger_name":"quickfixj.event"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Created session: FIXT.1.1:SANUUATFIX->RTNSFIXUAT","thread_name":"main","@timestamp":"2024-01-08T15:34:40.033+0000","level":"INFO","logger_name":"quickfixj.event"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Socket option: SocketTcpNoDelay=true","thread_name":"main","@timestamp":"2024-01-08T15:34:40.053+0000","level":"INFO","logger_name":"quickfix.mina.NetworkingOptions"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Socket option: SocketSynchronousWrites=false","thread_name":"main","@timestamp":"2024-01-08T15:34:40.053+0000","level":"INFO","logger_name":"quickfix.mina.NetworkingOptions"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Socket option: SocketSynchronousWriteTimeout=30000","thread_name":"main","@timestamp":"2024-01-08T15:34:40.053+0000","level":"INFO","logger_name":"quickfix.mina.NetworkingOptions"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Configured socket addresses for session: [XXX.net/XXX.XX.XX.XXX:16003]","thread_name":"main","@timestamp":"2024-01-08T15:34:40.520+0000","level":"INFO","logger_name":"quickfixj.event"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"SessionTimer started","thread_name":"main","@timestamp":"2024-01-08T15:34:40.522+0000","level":"INFO","logger_name":"quickfix.SocketInitiator"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Started QFJ Message Processor","thread_name":"QFJ Message Processor","@timestamp":"2024-01-08T15:34:40.526+0000","level":"INFO","logger_name":"quickfix.SocketInitiator"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Pending connection not established after 4008 ms.","thread_name":"QFJ Timer","@timestamp":"2024-01-08T15:34:44.531+0000","level":"INFO","logger_name":"quickfixj.event"}
{"@Version":1,"source_host":"fix-adapter-APP-current-43-qt7dm","message":"Pending connection not established after 9010 ms.","thread_name":"QFJ Timer","@timestamp":"2024-01-08T15:34:49.533+0000","level":"INFO","logger_name":"quickfixj.event"}

[chrjohn]

Pending connection not established after ...

To me it looks like there is a network timeout. Could you double check the network connection?
Are you able to verify that the connection works without proxy?

[AndreAfonso87]

Yes the network connection through proxy works, i did a curl/telnet cmd and it connects. We also have other environments that connect without proxy just fine. But we have requirement for this particular environment it needs to be through proxy. I find it weird that in the startup logs there is no mention to using proxy, should there be?

[AndreAfonso87]

Also we checked the proxy and there is no trace that the application is trying to connect through the proxy

[chrjohn]

Also we checked the proxy and there is no trace that the application is trying to connect through the proxy

How could there be a trace when the connection times out? ;)

Did you check if you need one of the other proxy options? https://rawgit.com/quickfix-j/quickfixj/master/quickfixj-core/src/main/doc/usermanual/usage/configuration.html

[AndreAfonso87]

Well, if it tried to connect through the proxy and failed afterwards, lets say like a firewall.... But its not like that its not even hitting the proxy.
The proxy doesn't need user or password, because we have other applications (different technology) that connect through proxy and doesn't have it either.
Is there any way to increase logging, to understand if its trying to use proxy even?

[AndreAfonso87]

Sorry for the delay, only managed to do it today. Attached the jmap histo file. I also have a dump, but its too big to annex here.
Uploading jmap_histo.txt…

[AndreAfonso87]

jmap_histo.txt

[chrjohn]

OK, so what do you want me to do now? ;) I think you can check for yourself if there are instances of InitiatorProxyIoHandler in the output. :)

BTW could you post the curl command that you use to verify that the connection through the proxy is working?

[AndreAfonso87]

I do not understand why its not working. We are calling:
SocketInitiator(fixApplication, storeFactory, sessionHandler.getSessionSettings(), logFactory, messageFactory);
Which if im seing this correctly it then calls createInitiator and inside its checking if it has properties ProxyType ProxyHost & ProxyPort
But its not working. i Guess its something to do with the properties file, but it seems fine i don't know what it could be.
Attached the curl cmd test with the proxy

[chrjohn]

You have SocketLocalPort=5430 in your settings. Is there a reason for this? I can't see it specified in the curl command, so try to remove it from the settings.
Also try setting ProxyVersion=1.1.
Moreover you are not using SSL in the curl command, so in the end you cannot really compare it to the QFJ setup.

[AndreAfonso87]

Fixed now. For future reference, using URL in SocketConnectionHost did not work. I had to open firewall specifically to the ip address and static ip address instead of url on SocketConnectionHost.

Thanks for your help

[chrjohn]

Glad that you managed to find the issue and thanks for sharing it here. 👍