Event CONNECTION_LOST not called in client?

[asaur]

Hello,

I've been messing around a bit with HTML 5 websocket connections to a SmartFoxServer2 (version 2.4.0) server, using the automatic zone 'force logout' feature. While doing this, I stumbled upon an issue that I need to understand better.

To better illustrate my questions, I'm putting here a lot of logs, taken from the server and the clients.

Phase 1 - Client '110496' logs in (called user 'A' afterwards):

Code: Select all

13:07:45 INFO  [New I/O  worker #1] c.s.b.s.DefaultSessionManager:222 - Session created: { Id: 5, Type: WEBSOCKET, Logged: No, IP: 192.168.200.118 } on Server port: 8888 <---> 59844
13:07:47 DEBUG [pool-2-thread-2] c.g.g.s.AbstractEventHandler:176 - handleServerEvent, eventUSER_LOGIN
13:07:47 DEBUG [pool-2-thread-2] c.g.g.s.AbstractEventHandler:166 - Calling doPlayerAuthentication username:110496 password:db989026be1b2e4b90cbf54e06706073 PlayerAuthentication:SmartFoxPlayerAuthentication [userId=110496, token=..., platformName=null, gameName=null]
13:07:47 DEBUG [pool-2-thread-2] c.g.g.t.e.ZoneExtension:113 - Executing authentication...
13:07:47 DEBUG [pool-2-thread-2] c.g.g.t.e.ZoneExtension:122 - Starting login phase: SmartFoxPlayerAuthentication [userId=110496, token=..., platformName=null, gameName=null]
13:07:47 INFO  [pool-2-thread-2] c.s.v.a.SFSApi:455 - User login: { Zone: TexasHoldem }, ( User Name: 110496, Id: 9, Priv: 0, Sess: 192.168.200.118:59844 ) , Type: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.11 (KHTML, like Gecko) Chrome/23.0.1271.95 Safari/537.11
13:07:47 DEBUG [pool-2-thread-2] c.g.g.s.AbstractEventHandler:176 - handleServerEvent, eventUSER_JOIN_ZONE
13:07:47 DEBUG [pool-2-thread-1] c.g.g.s.AbstractEventHandler:176 - handleServerEvent, eventUSER_JOIN_ROOM
13:07:47 DEBUG [pool-2-thread-2] c.g.g.s.c.CommandResponse:159 - Sending command response... CommandResponse [...]
13:07:47 DEBUG [pool-2-thread-1] c.g.g.t.c.PokerCommandFactory:19 - PokerCommandFactory: USER_JOIN_ROOM
13:07:47 DEBUG [pool-2-thread-2] c.g.g.s.AbstractEventHandler:113 - Finished , command... Name:[USER_JOIN_ZONE]
13:07:47 DEBUG [pool-2-thread-1] c.g.g.s.AbstractEventHandler:96 - Executing command... Name:[USER_JOIN_ROOM] , ...]
13:07:47 DEBUG [pool-2-thread-1] c.g.g.s.AbstractEventHandler:113 - Finished , command... Name:[USER_JOIN_ROOM]

So, user A is now connected and has joined the LOBBY room.

Phase 2 - Same client tries to connect again, coming from the same machine, but different browser (called user 'B' afterwards):

Code: Select all

13:08:06 INFO  [New I/O  worker #2] c.s.b.s.DefaultSessionManager:222 - Session created: { Id: 6, Type: WEBSOCKET, Logged: No, IP: 192.168.200.118 } on Server port: 8888 <---> 59849
13:08:08 DEBUG [pool-2-thread-3] c.g.g.s.AbstractEventHandler:176 - handleServerEvent, eventUSER_LOGIN
13:08:08 DEBUG [pool-2-thread-3] c.g.g.s.AbstractEventHandler:166 - Calling doPlayerAuthentication username:110496 password:c785ac525d36e063f77889057cbab5e1 PlayerAuthentication:SmartFoxPlayerAuthentication [userId=110496, token=..., platformName=null, gameName=null]
13:08:08 DEBUG [pool-2-thread-3] c.g.g.t.e.ZoneExtension:113 - Executing authentication...
13:08:08 DEBUG [pool-2-thread-3] c.g.g.t.e.ZoneExtension:122 - Starting login phase: SmartFoxPlayerAuthentication [userId=110496, token=..., platformName=null, gameName=null]
13:08:08 INFO  [pool-2-thread-3] c.s.v.e.SFSZone:1499 - User already logged in. Disconnecting previous instance : ( User Name: 110496, Id: 9, Priv: 0, Sess: 192.168.200.118:59844 )
13:08:08 INFO  [pool-2-thread-3] c.s.v.e.SFSZone:1204 - User: 110496 was disconnected.
13:08:08 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:176 - handleServerEvent, eventUSER_DISCONNECT
13:08:08 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:96 - Executing command... Name:[USER_DISCONNECT] , ...]
13:08:08 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:113 - Finished , command... Name:[USER_DISCONNECT]
13:08:08 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:176 - handleServerEvent, eventUSER_DISCONNECT
13:08:08 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:96 - Executing command... Name:[USER_DISCONNECT] , ...]
13:08:08 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:113 - Finished , command... Name:[USER_DISCONNECT]
13:08:08 INFO  [pool-2-thread-3] c.s.v.a.SFSApi:311 - User disconnected: { Zone: TexasHoldem }, ( User Name: 110496, Id: 9, Priv: 0, Sess: 192.168.200.118:59844 ) , SessionLen: 21220, Type: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.11 (KHTML, like Gecko) Chrome/23.0.1271.95 Safari/537.11
13:08:10 INFO  [pool-3-thread-1] c.s.v.a.SFSApi:455 - User login: { Zone: TexasHoldem }, ( User Name: 110496, Id: 11, Priv: 0, Sess: 192.168.200.118:59849 ) , Type: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:17.0) Gecko/20100101 Firefox/17.0
13:08:10 DEBUG [pool-2-thread-2] c.g.g.s.AbstractEventHandler:176 - handleServerEvent, eventUSER_JOIN_ZONE
13:08:10 DEBUG [pool-2-thread-2] c.g.g.s.c.CommandResponse:159 - Sending command response... CommandResponse [...]
13:08:10 DEBUG [pool-2-thread-2] c.g.g.s.AbstractEventHandler:113 - Finished , command... Name:[USER_JOIN_ZONE]
13:08:10 DEBUG [pool-2-thread-1] c.g.g.s.AbstractEventHandler:96 - Executing command... Name:[USER_JOIN_ROOM] , ...]
13:08:10 DEBUG [pool-2-thread-1] c.g.g.s.AbstractEventHandler:113 - Finished , command... Name:[USER_JOIN_ROOM]

As you can see, the previous connection (user A, WEBSOCKET port 59844) between the client and the server has been dropped automatically, right after the authentication phase (as it should). However, the web client was not notified of this server event, because nothing has been reported back in the browser's log console. This is the last line of the log, taken from user A, right after the server authenticated user B:

Code: Select all

[INFO] INCOMING DATA
a: 13 (Num)
p: [Object]
	p: [Object]
		cmdData: {...} (Str)
	c: USER_JOIN_ZONE (Str)
c: 1 (Num)
 SFS2X_API_JS.js:141
[INFO] IN < ExtensionResponse

So, user A does not know the connection has been dropped by the server, even as I configured a listener for that event (SFSEvent.CONNECTION_LOST -> function _onConnectionLost(event)).

Furthermore, user B (WEBSOCKET port 59849) receives the same response from the server:

Code: Select all

[INFO] INCOMING DATA
a: 13 (Num)
p: [Object]
	p: [Object]
		cmdData: {...} (Str)
	c: USER_JOIN_ZONE (Str)
c: 1 (Num)

SFS2X_API_JS.js (linha 141)

[INFO] IN < ExtensionResponse

Phase 3 - After a while, the server detects that something wrong happened to the connection from websocket 59844, generating the following log:

Code: Select all

13:09:49 WARN  [Scheduler1-thread-1] bootLogger - Scheduler callback exception. Callback: com.smartfoxserver.bitswarm.sessions.DefaultSessionManager$SessionCleaner@1ea3beba, Exception: com.smartfoxserver.v2.exceptions.SFSRuntimeException: IdleSession event ignored, cannot find any User for Session: { Id: 5, Type: WEBSOCKET, Logged: Yes, IP: 192.168.200.118:59844 }
        com.smartfoxserver.v2.SmartFoxServer.onSessionIdle(SmartFoxServer.java:957)
        com.smartfoxserver.v2.SmartFoxServer.access$3(SmartFoxServer.java:952)
        com.smartfoxserver.v2.SmartFoxServer$NetworkEvtListener.handleEvent(SmartFoxServer.java:1029)
        com.smartfoxserver.bitswarm.service.BaseCoreService.dispatchEvent(BaseCoreService.java:110)
        com.smartfoxserver.bitswarm.sessions.DefaultSessionManager.dispatchSessionIdleEvent(DefaultSessionManager.java:818)
        com.smartfoxserver.bitswarm.sessions.DefaultSessionManager.applySessionCleaning(DefaultSessionManager.java:733)
        com.smartfoxserver.bitswarm.sessions.DefaultSessionManager.access$0(DefaultSessionManager.java:698)
        com.smartfoxserver.bitswarm.sessions.DefaultSessionManager$SessionCleaner.doTask(DefaultSessionManager.java:87)
        com.smartfoxserver.bitswarm.util.scheduling.Scheduler.executeTasks(Scheduler.java:214)
        com.smartfoxserver.bitswarm.util.scheduling.Scheduler.run(Scheduler.java:152)
        java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
        java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        java.lang.Thread.run(Unknown Source)
13:09:59 INFO  [New I/O  worker #1] c.s.b.s.DefaultSessionManager:276 - Session removed: { Id: 5, Type: WEBSOCKET, Logged: Yes, IP: 192.168.200.118:59844 }
13:09:59 INFO  [Scheduler1-thread-1] c.s.b.s.DefaultSessionManager:276 - Session removed: { Id: 5, Type: WEBSOCKET, Logged: Yes, IP: 192.168.200.118:59844 }
13:09:59 INFO  [Scheduler1-thread-1] c.s.b.s.DefaultSessionManager:713 - Terminated idle logged-in session: { Id: 5, Type: WEBSOCKET, Logged: Yes, IP: 192.168.200.118:59844 }

I can understand the server exception, even if it's a bit odd - after all, inside the server, user A's connection was already dropped, as a consequence to the 'forceLogout' feature.

In the client, user A did not receive any events, that is, no data has been received in the socket, so I'm guessing the client connection is still active. After a while, something happens, and I print the following on-screen message:

'You have been disconnected. Reason: unknown'

This comes from the '_onConnectionLost(event)' event handler.

Phase 4 - Server detects that a connection has been idle for too long in websocket 59849, generating the following log:

Code: Select all

13:10:19 INFO  [New I/O  worker #2] c.s.b.s.DefaultSessionManager:276 - Session removed: { Id: 6, Type: WEBSOCKET, Logged: Yes, IP: 192.168.200.118:59849 }
13:10:19 INFO  [New I/O  worker #2] c.s.v.e.SFSZone:1204 - User: 110496 was disconnected.
13:10:19 INFO  [New I/O  worker #2] c.s.v.a.SFSApi:311 - User disconnected: { Zone: TexasHoldem }, ( User Name: 110496, Id: 11, Priv: 0, Sess: 192.168.200.118:59849 ) , SessionLen: 129252, Type: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:17.0) Gecko/20100101 Firefox/17.0
13:10:19 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:176 - handleServerEvent, eventUSER_DISCONNECT
13:10:19 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:96 - Executing command... Name:[USER_DISCONNECT] , ...]
13:10:19 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:113 - Finished , command... Name:[USER_DISCONNECT]
13:10:19 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:176 - handleServerEvent, eventUSER_DISCONNECT
13:10:19 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:96 - Executing command... Name:[USER_DISCONNECT] , ...]
13:10:19 DEBUG [pool-2-thread-4] c.g.g.s.AbstractEventHandler:113 - Finished , command... Name:[USER_DISCONNECT]

This, in turn, generates the following log in user's B console:

Code: Select all

[INFO] INCOMING DATA
a: 1005 (Num)
p: [Object]
	dr: 0 (Num)
c: 0 (Num)

SFS2X_API_JS.js (linha 141)

[INFO] IN < ClientDisconnection

Which prints the same message on user's B screen:

'You have been disconnected. Reason: idle'

So, finally, here come the questions:

1 - Does the USER_DISCONNECT server event not trigger a SFSEvent.CONNECTION_LOST event?
2 - Is that the intended behaviour? I mean, why not as soon as the server detected a second login from the same user and disconnected the first, send a disconnection event to the first (disconnected) client?
3 - The disconnect event logged in user's A screen was caused by whom? I mean, since the browser didn't receive any data, I'm guessing the client itself terminated the connection. Is that correct?

Sorry for the long post, but I couldn't find any way to reduce it and actually explain myself.

[Bax]

Thank you for reporting. We will look into it.

[Lapo]

Thanks for reporting. We'll be releasing an update next week which will address this proble as well.