Error: User already logged in. Disconnecting previous instance

[Bert]

Hi,

Some times the server gets in this state, and every attempt to connect/login results in this error: "User already logged in. Disconnecting previous instance", and the server initiates a disconnect of the session, and then the client gets the disconnected error.

This is on a development server.. no other users or client instances running. I am running the server on my local computer. Client connects to localhost:9933. We are not initiating multiple connects / logins. Client is single-threaded. And we have the client dumping all logs (including SFS's data) to a file.

We are using:

• SFS2X v2.17
• Client is Unity, (Client API v.1.7.13).
• This is running on Windows 10.
• Unity version 2020.2.5

When this happens the only solution is to restart the SFS2x server.

Is there something we are doing to cause this error?

Thanks in advance.

This is the log:

16:13:58,069 INFO [SocketReader] sessions.DefaultSessionManager - Session created: { Id: 85, Type: DEFAULT, Logged: No, IP: 0:0:0:0:0:0:0:1:2381 } on Server port: 9933 <---> 2381
16:13:58,340 INFO [SFSWorker:Ext:2] api.SFSApi - User login: { Zone: Farm }, ( User Name: U-1561844030, Id: 81, Priv: 0, Sess: 0:0:0:0:0:0:0:1:2381 ) , Type: Unity / .Net
16:13:58,341 INFO [SFSWorker:Ext:2] scala.DefLI - User already logged in. Disconnecting previous instance : ( User Name: U-1561844030, Id: 81, Priv: 0, Sess: 0:0:0:0:0:0:0:1:2381 )
16:13:58,341 INFO [SFSWorker:Ext:3] Extensions - {FTExtension}: SFSEventType.USER_JOIN_ZONE - ( User Name: U-1561844030, Id: 81, Priv: 0, Sess: 0:0:0:0:0:0:0:1:2381 )
16:13:58,341 INFO [SFSWorker:Ext:2] sessions.DefaultSessionManager - Session removed: { Id: 85, Type: DEFAULT, Logged: Yes, IP: 0:0:0:0:0:0:0:1:2381 }

[Lapo]

Hi,
the two logins are logged as 1ms apart, and they are coming from the same port, so it's the same connection.
It should be easy to see what is going on if you activate the DEBUG logs on the server side.
( see here: http://docs2x.smartfoxserver.com/Gettin ... figuration )

Does your Extension validate the login credentials?
If so can we see the relative code? (you can use a private message, if you prefer)

Also, is this something that you can reproduce consistently?

Thanks

[Bert]

Hi Lapo,

Thanks for the prompt response.

Which lines indicate 2 logins? Is the 'User already logged in' an error message referring to the previous login, or is this line indicating a 2nd login?

Our extension doesn't validate login credentials, but it uses a custom login handler to forward some data to the USER_JOIN_ZONE handler.

I cannot reproduce it consistently. However, when the server gets in this 'mode', every login attempt fails the same way. Restarting the client, or asking the client to reconnect all results in the same behavior.

When my client sends the LoginRequest, it passes some data to the server in the 'parameters' argument, that gets received by our server extension in the USER_LOGIN handler in the LOGIN_IN_DATA.

This is the handler for USER_LOGIN:

Code: Select all

@Instantiation(Instantiation.InstantiationMode.SINGLE_INSTANCE)
public class LoginEventHandler extends BaseServerEventHandler {

    @Override
    public void handleServerEvent(ISFSEvent event) throws SFSException {

        ISFSObject loginInData = (ISFSObject) event.getParameter(SFSEventParam.LOGIN_IN_DATA);
        Session    session     = (Session) event.getParameter(SFSEventParam.SESSION);

        if (session != null && loginInData != null) {
            session.setProperty("LoginData", loginInData);
        }
    }
}

This is the log from the client with DEBUG activated:

Code: Select all

----------------- MyAdapter.Connect: localhost:9933
SFS.Log - INFO: Data written: Binary Size: 53
12 00 03 00 01 63 02 00 00 01 61 03 00 00 00 01    .....c....a.....
70 12 00 02 00 03 61 70 69 08 00 06 31 2e 37 2e    p.....api...1.7.
31 33 00 02 63 6c 08 00 0c 55 6e 69 74 79 20 2f    13..cl...Unity./
20 2e 4e 65 74                                     ..Net           

SFS.Log - INFO: Data Read: Binary Size: 80
80 00 4d 12 00 03 00 01 70 12 00 03 00 02 63 74    ..M.....p.....ct
04 00 00 04 00 00 02 6d 73 04 00 07 a1 20 00 02    .......ms.......
74 6b 08 00 20 32 30 30 37 61 38 30 38 32 65 36    tk...2007a8082e6
30 32 64 32 30 32 33 61 64 64 31 36 34 37 65 38    02d2023add1647e8
31 38 63 66 38 00 01 61 03 00 00 00 01 63 02 00    18cf8..a.....c..

SFS.Log - INFO: Message: Handshake { Message id: 0 }
{ Dump: }

   (int) ct: 1024
   (int) ms: 500000
   (utf_string) tk: 2007a8082e602d2023add1647e818cf8
MyAdapter.OnConnectionHandler - - SFSEvent.CONNECTION, success: True



---------------- MyAdapter.SendLoginRequest
SFS.Log - INFO: Data written: Binary Size: 691
12 00 03 00 01 63 02 00 00 01 61 03 00 01 00 01    .....c....a.....
70 12 00 04 00 02 7a 6e 08 00 04 46 61 72 6d 00    p.....zn...Farm.
02 75 6e 08 00 0c 55 2d 31 35 36 31 38 34 34 30    .un...U-15618440
33 30 00 02 70 77 08 00 20 32 64 37 61 63 32 39    30..pw...2d7ac29
38 64 62 30 64 34 32 38 64 30 34 36 61 31 30 66    8db0d428d046a10f
65 65 66 38 63 33 34 62 62 00 01 70 12 00 02 00    eef8c34bb..p....
03 63 6d 64 08 00 0f 53 23 43 6f 6d 6d 61 6e 64    .cmd...S#Command
5f 42 61 74 63 68 00 01 30 11 00 02 12 00 0c 00    _Batch..0.......
03 5f 49 64 08 00 0a 31 35 36 31 38 34 34 30 33    ._Id...156184403
30 00 05 5f 4e 61 6d 65 08 00 03 45 6c 66 00 05    0.._Name...Elf..
5f 48 69 6e 74 08 00 00 00 05 5f 4d 6f 6f 64 08    _Hint....._Mood.
00 00 00 0e 5f 4c 61 6e 67 75 61 67 65 5f 43 6f    ...._Language_Co
64 65 08 00 02 65 6e 00 06 5f 43 6f 6c 6f 72 04    de...en.._Color.
00 00 00 00 00 0a 5f 42 75 64 64 79 5f 49 64 73    ......_Buddy_Ids
08 00 2b 31 35 31 38 33 31 39 30 37 36 2c 31 36    ..+1518319076,16
30 33 37 35 36 35 38 35 2c 31 32 31 32 30 33 32    03756585,1212032
38 32 39 2c 31 36 32 35 32 38 38 30 31 33 00 0e    829,1625288013..
5f 4e 65 69 67 68 62 6f 75 72 5f 49 64 73 08 00    _Neighbour_Ids..
2b 31 35 31 38 33 31 39 30 37 36 2c 31 36 30 33    +1518319076,1603
37 35 36 35 38 35 2c 31 32 31 32 30 33 32 38 32    756585,121203282
39 2c 31 36 32 35 32 38 38 30 31 33 00 05 5f 49    9,1625288013.._I
6e 66 6f 12 00 0c 00 02 69 64 08 00 0a 31 35 36    nfo.....id...156
31 38 34 34 30 33 30 00 04 6e 61 6d 65 08 00 03    1844030..name...
45 6c 66 00 06 61 76 61 74 61 72 08 00 1d 54 62    Elf..avatar...Tb
6f 79 2c 48 31 30 2c 45 31 2c 52 31 2c 42 36 2c    oy,H10,E1,R1,B6,
4d 31 2c 4e 32 2c 53 32 2c 47 37 00 08 63 6c 6f    M1,N2,S2,G7..clo
74 68 69 6e 67 08 00 00 00 07 70 69 63 5f 75 72    thing.....pic_ur
6c 08 00 00 00 05 6c 65 76 65 6c 04 00 00 00 19    l.....level.....
00 02 78 70 05 00 00 00 00 00 00 53 6a 00 0c 6c    ..xp.......Sj..l
65 76 65 6c 5f 78 70 5f 6d 69 6e 05 00 00 00 00    evel_xp_min.....
00 00 4e 20 00 0c 6c 65 76 65 6c 5f 78 70 5f 6d    ..N...level_xp_m
61 78 05 00 00 00 00 00 00 61 a8 00 05 74 69 74    ax.......a...tit
6c 65 08 00 10 41 63 63 6c 61 69 6d 65 64 20 46    le...Acclaimed.F
61 72 6d 65 72 00 08 74 72 6f 70 68 69 65 73 08    armer..trophies.
00 11 43 30 2c 56 30 2c 43 31 2c 43 32 2c 56 31    ..C0,V0,C1,C2,V1
2c 43 33 00 0f 68 61 73 5f 63 6f 6f 70 5f 71 75    ,C3..has_coop_qu
65 73 74 73 01 00 00 02 5f 58 04 ff ff ff ff 00    ests...._X......
02 5f 59 04 ff ff ff ff 00 03 63 6d 64 08 00 09    ._Y.......cmd...
53 23 43 6f 6e 6e 65 63 74 12 00 04 00 03 63 6d    S#Connect.....cm
64 08 00 13 53 23 4a 6f 69 6e 5f 52 6f 6f 6d 5f    d...S#Join_Room_
52 65 71 75 65 73 74 00 01 30 08 00 0f 66 61 72    Request..0...far
6d 2d 31 35 36 31 38 34 34 30 33 30 00 01 31 08    m-1561844030..1.
00 05 65 6e 5f 55 53 00 01 32 05 00 00 00 00 00    ..en_US..2......
00 00 00                                           ...             

SFS.Log - INFO: Data Read: Binary Size: 280
80 01 15 12 00 03 00 01 70 12 00 06 00 02 72 73    ........p.....rs
03 00 00 00 02 7a 6e 08 00 04 46 61 72 6d 00 02    .....zn...Farm..
75 6e 08 00 0c 55 2d 31 35 36 31 38 34 34 30 33    un...U-156184403
30 00 02 70 69 03 00 00 00 02 72 6c 11 00 04 11    0..pi.....rl....
00 09 04 00 00 00 02 08 00 09 54 65 73 74 2d 52    ..........Test-R
6f 6f 6d 08 00 07 64 65 66 61 75 6c 74 01 00 01    oom...default...
00 01 00 03 00 00 03 00 14 11 00 00 11 00 09 04    ................
00 00 00 03 08 00 0f 66 61 72 6d 2d 31 35 36 31    .......farm-1561
38 34 34 30 33 30 08 00 07 64 65 66 61 75 6c 74    844030...default
01 00 01 00 01 00 03 00 00 03 00 14 11 00 00 11    ................
00 09 04 00 00 00 04 08 00 0b 6d 61 72 6b 65 74    ..........market
70 6c 61 63 65 08 00 07 64 65 66 61 75 6c 74 01    place...default.
00 01 00 01 00 03 00 00 03 00 14 11 00 00 11 00    ................
09 04 00 00 00 05 08 00 12 66 61 72 6d 2d 31 35    .........farm-15
31 38 33 31 39 30 37 36 2d 33 37 08 00 07 64 65    18319076-37...de
66 61 75 6c 74 01 00 01 00 01 00 03 00 00 03 00    fault...........
14 11 00 00 00 02 69 64 04 00 00 00 24 00 01 61    ......id....$..a
03 00 01 00 01 63 02 00                            .....c..       

SFS.Log - INFO: Message: Login { Message id: 1 }
{ Dump: }

   (short) rs: 0
   (utf_string) zn: Farm
   (utf_string) un: U-1561844030
   (short) pi: 0
   (sfs_array) rl:
      (sfs_array)
         (int) 2
         (utf_string) Test-Room
         (utf_string) default
         (bool) False
         (bool) False
         (bool) False
         (short) 0
         (short) 20
         (sfs_array)
            
         
      
      (sfs_array)
         (int) 3
         (utf_string) farm-1561844030
         (utf_string) default
         (bool) False
         (bool) False
         (bool) False
         (short) 0
         (short) 20
         (sfs_array)
            
         
      
      (sfs_array)
         (int) 4
         (utf_string) marketplace
         (utf_string) default
         (bool) False
         (bool) False
         (bool) False
         (short) 0
         (short) 20
         (sfs_array)
            
         
      
      (sfs_array)
         (int) 5
         (utf_string) farm-1518319076-37
         (utf_string) default
         (bool) False
         (bool) False
         (bool) False
         (short) 0
         (short) 20
         (sfs_array)
            
         
      
   
   (int) id: 36

------------- MyAdapter.OnLoginHandler - user: [User: U-1561844030, Id: 36, isMe: True]
SFS.Log - LogLevel.ERROR: [TCPSocketLayer] Connection closed by the remote side


[Lapo]

Which lines indicate 2 logins? Is the 'User already logged in' an error message referring to the previous login, or is this line indicating a 2nd login?

You are right, the log fragment you have posted is kind of incomplete, as the first session is not visible.

Here's an example where two connections attempt to login with the same user name:

Code: Select all

16:10:27,247 INFO  [SocketReader] sessions.DefaultSessionManager     - Session created: { Id: 5, Type: DEFAULT, Logged: No, IP: 0:0:0:0:0:0:0:1:62498 } on Server port: 9933 <---> 62498
16:10:27,291 INFO  [SFSWorker:Sys:3] api.SFSApi     - User login: { Zone: BasicExamples }, ( User Name: Test, Id: 1, Priv: 0, Sess: 0:0:0:0:0:0:0:1:62498 ) , Type: Flash
16:10:32,262 INFO  [SocketReader] sessions.DefaultSessionManager     - Session created: { Id: 6, Type: DEFAULT, Logged: No, IP: 0:0:0:0:0:0:0:1:62499 } on Server port: 9933 <---> 62499
16:10:32,313 INFO  [SFSWorker:Sys:4] scala.DefLI     - User already logged in. Disconnecting previous instance : ( User Name: Test, Id: 1, Priv: 0, Sess: 0:0:0:0:0:0:0:1:62498 )
16:10:32,314 INFO  [SFSWorker:Sys:4] sessions.DefaultSessionManager     - Session removed: { Id: 5, Type: DEFAULT, Logged: Yes, IP: 0:0:0:0:0:0:0:1:62498 }
16:10:32,314 INFO  [SFSWorker:Sys:4] api.SFSApi     - User disconnected: { Zone: BasicExamples }, ( User Name: Test, Id: 1, Priv: 0, Sess: 0:0:0:0:0:0:0:1:62498 ) , SessionLen: 5024, Type: Flash
16:10:34,319 INFO  [pool-1-thread-1] api.SFSApi     - User login: { Zone: BasicExamples }, ( User Name: Test, Id: 2, Priv: 0, Sess: 0:0:0:0:0:0:0:1:62499 ) , Type: Flash

Can you show me the client side code used for this test?
Do you also listen for the USER_JOIN_ZONE event on the server side?

Thanks

[Bert]

Yes, the server extension has a handler for USER_JOIN_ZONE.

I just realized that the issue happens after I build the server extension in IntelliJ and the VM does a hot swap of the modified classes.

This is the client code:

Code: Select all

   public class SfsAdapter : MonoBehaviour
   {
      private string hostName;
      private int portNumber = 9933;

      private SFSObject LoginParams;

      public void Connect( string host, string zoneName, SFSObject loginParams  )
      {
         this.InitSmartfox();

         this.hostName = host;
         this.LoginParams = loginParams;

         var configData = new ConfigData
         {
            Host = this.hostName,
            Port = this.portNumber,
            Zone = zoneName,
#if UNITY_EDITOR
            Debug = true
#endif
         };

         this.SmartFox.Connect(configData);
      }
   
      private void InitSmartfox()
      {
#if UNITY_EDITOR
         this.SmartFox = new SmartFox();
         this.SmartFox.Debug = true;
         this.SmartFox.Logger.LoggingLevel = LogLevel.DEBUG;

         this.portNumber = 9933;
#else
         var useWss = !UnityEngine.Debug.isDebugBuild;      // WebGL build, in Dev mode.. local browser test.. don't use WSS.
         this.SmartFox = new SmartFox(useWss ? Sfs2X.Util.UseWebSocket.WSS_BIN : Sfs2X.Util.UseWebSocket.WS_BIN);

         this.portNumber = useWss ? 443 : 80;
#endif

         this.SmartFox.ThreadSafeMode = true;


         this.SmartFox.RemoveAllEventListeners();
         this.SmartFox.AddEventListener(SFSEvent.CONNECTION, this.OnConnectionHandler);
         this.SmartFox.AddEventListener(SFSEvent.CONNECTION_LOST, this.OnConnectionLostHandler);
         this.SmartFox.AddEventListener(SFSEvent.CONNECTION_RETRY, this.OnConnectionRetryHandler);
         this.SmartFox.AddEventListener(SFSEvent.CONNECTION_RESUME, this.OnConnectionResumeHandler);

         this.SmartFox.AddEventListener(SFSEvent.LOGIN, this.OnLoginHandler);
         this.SmartFox.AddEventListener(SFSEvent.LOGIN_ERROR, this.OnLoginErrorHandler);

         this.SmartFox.AddEventListener(SFSEvent.EXTENSION_RESPONSE, this.OnExtensionResponseHandler);

         this.SmartFox.AddLogListener(LogLevel.INFO, this.OnInfoMessage);
         this.SmartFox.AddLogListener(LogLevel.WARN, this.OnWarnMessage);
         this.SmartFox.AddLogListener(LogLevel.ERROR, this.OnErrorMessage);
      }

      private void OnConnectionHandler(BaseEvent evt)
      {
         var success = evt.Params.ContainsKey("success") && (bool) evt.Params["success"];
         this.State = success ? SmartfoxState.Connected : SmartfoxState.ConnectError;
         CBLog.Info("SFS.OnConnectionHandler - success: {0}", success);
         if (success)
         {
            this.SendLoginRequest(this.Config.SmartFoxZone);
         }
         else
         {
            this.OnConnectAndLoginFailed("SFS.Connect: Failed", this.hostName + ":" + this.portNumber);
         }
      }

      private void SendLoginRequest(string zoneName)
      {
         CBLog.Info("---------------- SFS.SendLoginRequest");

         // Try to Login
         string userName = "U-" + GameState._User_Id;
         string password = Globals.MD5Utils.GetMD5Hash("......");

         this.State = SmartfoxState.LoginInProgress;
         this.SmartFox.Send(new LoginRequest(userName, password, zoneName, parameters:this.LoginParams));
      }

      private void OnLoginHandler(BaseEvent evt)
      {
         this.State = SmartfoxState.LoginSuccess;

         this.User = evt.Params.ContainsKey("user") ? (User) evt.Params["user"] : null;
         this.Room = null;

         CBLog.Info($"------------- SFS.OnLoginHandler - user: {User}");
      }


      #region Logging

      private void OnInfoMessage(BaseEvent evt)
      {
         string message = (string) evt.Params["message"];
         CBLog.Info("SFS: {0}", message);
      }

      private void OnWarnMessage(BaseEvent evt)
      {
         string message = (string) evt.Params["message"];
         CBLog.Info("WARN: SFS: {0}", message);
      }

      private void OnErrorMessage(BaseEvent evt)
      {
         string message = (string) evt.Params["message"];
         CBLog.Info("ERROR: SFS: {0}", message);
      }

      #endregion

      private Update()
      {
         this.SmartFox.ProcessEvents();
      }
   }

[Lapo]

I just realized that the issue happens after I build the server extension in IntelliJ and the VM does a hot swap of the modified classes.

Does your Extension override the destroy() method?
If so make sure that the first line in the method is this:

Code: Select all

super.destroy()

In other words:

Code: Select all

@Override
public void destroy()
{
   super.destroy();

   // Your code
   // ....
}

Cheers

[Bert]

Hi Lapo,

This was exactly the problem. Added the call to the base and it all works fine now. Thanks for your help.

Does your Extension override the destroy() method?
If so make sure that the first line in the method is this:

Code: Select all

super.destroy()

[Lapo]

Excellent
The reason for this is that by calling super.destroy() the parent class can release all the attached event listeners.
The alternative would be to do it manually, but it's easier to just invoke the parent.

Cheers

[Bert]

Makes sense. Thanks!