Sending multiple logons
Closed this issue · 6 comments
The default behaviour for quickfix-messager seems to be to send continual logon requests (after a set period of time), even though the first logon request was successful.
Is this intended?
This might not be a problem, apart from I am sending a username and password with my logon - which seems to be fine for the first attempt. But subsequent logons do not appear to be including the username and password which could cause issues. The subsequent logons are causing my server logs to fill up with 'user already logged on' type messages.
Was the session established (i.e. received a corresponding logon response)?
QuickFIX will continue to retry sending a logon as long as the session is not established. You can configure the interval from quickfix.cfg by setting the ReconnectInterval (in seconds) property.
Note that this is a QuickFIX (engine) behavior an not a Messenger behavior.
I'll look into this over the weekend. But my server implementation is also using QuickFIX, so I was assuming that this was handled 'automatically'. Quickfix-messenger indicates that the session is logged on, and allows me to then send and receive subsequent messages (eg Market Data Request).
Kindly attach the quickfix log file so I can take a look as well.
So the qfix-messenger client initiator logs look like this:
20140822-16:31:56: Session FIX.4.4:INIT-CLIENT->ACCEPT-SERVER schedule is daily, 00:00:00-UTC - 00:00:00-UTC
20140822-16:31:56: Session state is not current; resetting FIX.4.4:INIT-CLIENT->ACCEPT-SERVER
20140822-16:31:56: Created session: FIX.4.4:INIT-CLIENT->ACCEPT-SERVER
20140822-16:31:57: Initiated logon request
20140822-16:32:01: Logon contains ResetSeqNumFlag=Y, resetting sequence numbers to 1
20140822-16:32:01: Received logon
20140822-16:32:28: Received logout request
20140822-16:32:28: Sent logout response
20140822-16:32:29: Initiated logon request
20140822-16:32:30: Logon contains ResetSeqNumFlag=Y, resetting sequence numbers to 1
20140822-16:32:30: Received logon
20140822-16:33:00: Received logout request
20140822-16:33:00: Sent logout response
20140822-16:33:01: Initiated logon request
20140822-16:33:02: Logon contains ResetSeqNumFlag=Y, resetting sequence numbers to 1
20140822-16:33:02: Received logon
20140822-16:33:04: Disconnecting: Socket exception (localhost/127.0.0.1:12344): java.io.IOException: An existing connection was forcibly closed by the remote host
And here is my server acceptor logs:
20140822-16:31:43: Session FIX.4.4:ACCEPT-SERVER->INIT-CLIENT schedule is daily, 00:00:00-UTC - 00:00:00-UTC
20140822-16:31:43: Created session: FIX.4.4:ACCEPT-SERVER->INIT-CLIENT
20140822-16:31:57: Accepting session FIX.4.4:ACCEPT-SERVER->INIT-CLIENT from /127.0.0.1:58229
20140822-16:31:57: Acceptor heartbeat set to 30 seconds
20140822-16:31:57: Logon contains ResetSeqNumFlag=Y, resetting sequence numbers to 1
20140822-16:32:01: Received logon
20140822-16:32:01: Responding to Logon request
20140822-16:32:28: Logon rejected: quickfix.RejectLogon: A Logon message must contain both a Username(553) and Password(554).
20140822-16:32:28: Already disconnected: Logon rejected: quickfix.RejectLogon: A Logon message must contain both a Username(553) and Password(554).
20140822-16:32:29: Accepting session FIX.4.4:ACCEPT-SERVER->INIT-CLIENT from /127.0.0.1:58244
20140822-16:32:29: Acceptor heartbeat set to 30 seconds
20140822-16:32:29: Logon contains ResetSeqNumFlag=Y, resetting sequence numbers to 1
20140822-16:32:30: Received logon
20140822-16:32:30: Responding to Logon request
20140822-16:33:00: Logon rejected: quickfix.RejectLogon: A Logon message must contain both a Username(553) and Password(554).
20140822-16:33:00: Disconnecting: Logon rejected: quickfix.RejectLogon: A Logon message must contain both a Username(553) and Password(554).
20140822-16:33:00: Application exception in onLogout()
java.lang.RuntimeException: Expunge latch already set from existing Logon
<- snip ->
20140822-16:33:01: Accepting session FIX.4.4:ACCEPT-SERVER->INIT-CLIENT from /127.0.0.1:58275
20140822-16:33:01: Acceptor heartbeat set to 30 seconds
20140822-16:33:01: Logon contains ResetSeqNumFlag=Y, resetting sequence numbers to 1
20140822-16:33:02: Received logon
20140822-16:33:02: Responding to Logon request
20140822-16:33:02: Application exception in onLogon()
java.lang.RuntimeException: Logon has already been confirmed
<- snip ->
Both these are running on the same machine, so the times should match up. I did wonder if a logon was being sent instead of a heartbeat?
So I can see that the client receives a logout request at 20140822-16:32:28 - but I don't think that my server initiates that. As I said, I'll investigate more over the weekend. Even so, the subsequent attempts by the client to log back in seem to rejected by my server because they don't include the username and password.
I'll also say that this doesn't stop me doing my (currently) very simple tests, but it does obviously start to clutter the logs a bit. I also add that I'm pretty new to FIX, so it's entirely possible I'm making an elementary mistake somewhere.
OK - time for me to apologise. Sorry!
This was totally my bug, as the heartbeats were being interpretted as a logon, simple because I left a single annotation in my code when I refactored a few months back. Qfix-messenger is the first 'proper' (3rd party) client that I've used againt my server, and this is the only issue that I've found so far.
So a big thanks for providing qfix-messenger, it's giving me a lot of confidence in what I've written.
Thanks!
awesome, glad it helped