Maybe bug with force logout in 2.17.3 not present in 2.16.0

Post here your questions about SFS2X. Here we discuss all server-side matters. For client API questions see the dedicated forums.

Moderators: Lapo, Bax

votagusvotag
Posts: 38
Joined: 07 Nov 2016, 12:26

Maybe bug with force logout in 2.17.3 not present in 2.16.0

Postby votagusvotag » 07 Oct 2021, 14:45

Hi, I just downloaded sfs v2.17.3 along with the c# client api v1.7.16 and testing in Windows I have a weird bug that cannot reproduce in my linux environment running 2.16.0.
First login goes well no problem at all, then if I stop the client and log in again, the server is configured to force logout so the current session is disconnected and a new one is created, then I get a npe in this line of my code

@Override
public void handleClientRequest(User user, ISFSObject data) {

extension = (ZoneExtension) getParentExtension();
this.user = user;
this.data = data;
userId = user.getVariable("user_id").getDoubleValue().longValue(); // npe here.


I'm testing in a local environment (windows) with only one user and my only guess is that somehow sfs is trying to access the destroyed version of this user, because user_id does exist, I can see it in the admin and we don't have this problem in other instances running 2.16.0.

This is the log.

11:29:52,807 INFO [SocketReader] sessions.DefaultSessionManager - Session created: { Id: 5, Type: DEFAULT, Logged: No, IP: 0:0:0:0:0:0:0:1:60675 } on Server port: 9933 <---> 60675
11:29:52,944 INFO [SFSWorker:Ext:4] zone.ZoneExtension - Login Type: 3
11:29:53,418 INFO [SFSWorker:Ext:4] scala.DefLI - User already logged in. Disconnecting previous instance : ( User Name: guest196, Id: 3, Priv: 0, Sess: 0:0:0:0:0:0:0:1:56688 )
11:29:53,419 INFO [SFSWorker:Ext:4] managers.SFSRoomManager - Room removed: { Zone: Crypto_Game }, [ Room: chat_room, Id: 3, Group: default, isGame: false ], Duration: 53113
11:29:53,428 INFO [SFSWorker:Ext:4] api.SFSApi - User disconnected: { Zone: Crypto_Game }, ( User Name: guest196, Id: 3, Priv: 0, Sess: 0:0:0:0:0:0:0:1:56688 ) , SessionLen: 53722, Type: WindowsEditor:1.0.2
11:29:53,428 DEBUG [SFSWorker:Ext:3] zone.ZoneExtension - OnUserDisconnectHandler START
11:29:53,430 DEBUG [SFSWorker:Ext:3] zone.ZoneExtension - OnUserDisconnectHandler END
11:29:53,430 DEBUG [pool-1-thread-4] zone.ZoneExtension - ExecuteUpdateRunnable INIT
11:29:53,914 DEBUG [pool-1-thread-4] zone.ZoneExtension - ExecuteUpdateRunnable END

11:29:54,963 INFO [Scheduler1-thread-1] sessions.DefaultSessionManager - Session removed: { Id: 4, Type: DEFAULT, Logged: No, IP: 0:0:0:0:0:0:0:1:56688 }
11:29:55,430 INFO [pool-1-thread-2] api.SFSApi - User login: { Zone: Crypto_Game }, ( User Name: guest196, Id: 4, Priv: 0, Sess: 0:0:0:0:0:0:0:1:60675 ) , Type: WindowsEditor:1.0.2
11:29:55,485 ERROR [SFSWorker:Ext:1] v290.ExtensionReqController - java.lang.NullPointerException:
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
Exception: java.lang.NullPointerException
Message: *** Null ***
Description: Error while handling client request in extension: { Ext: CryptoGameExtension, Type: JAVA, Lev: ZONE, { Zone: Crypto_Game }, {} }
Extension Cmd: user.myAvatars
+--- --- ---+
Stack Trace:
+--- --- ---+
com.hackembostudios.crypto_game.zone.handlers.UserHandler.handleClientRequest(UserHandler.java:48)
com.smartfoxserver.v2.extensions.SFSExtension.handleClientRequest(SFSExtension.java:208)
com.smartfoxserver.v2.controllers.v290.ExtensionReqController.processRequest(ExtensionReqController.java:174)
com.smartfoxserver.v2.controllers.v290.ExtensionReqController$1.run(ExtensionReqController.java:68)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
java.lang.Thread.run(Thread.java:748)
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
User avatar
Lapo
Site Admin
Posts: 22211
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Maybe bug with force logout in 2.17.3 not present in 2.16.0

Postby Lapo » 11 Oct 2021, 09:31

Hi,
(sorry for the delay in responding. I didn't get the notification because you posted under the old SFS 1.x section. I have now moved the post under SFS2X)

I'm testing in a local environment (windows) with only one user and my only guess is that somehow sfs is trying to access the destroyed version of this user, because user_id does exist, I can see it in the admin and we don't have this problem in other instances running 2.16.0.

You can print out the User id (which is unique) in your Extension call, so you can verify that the 2nd time the User logs in, it has a different id. If not, there might be something else going on.

Let us know
Lapo
--
gotoAndPlay()
...addicted to flash games
votagusvotag
Posts: 38
Joined: 07 Nov 2016, 12:26

Re: Maybe bug with force logout in 2.17.3 not present in 2.16.0

Postby votagusvotag » 15 Oct 2021, 18:49

First login.
15:43:06,092 INFO [SocketReader] sessions.DefaultSessionManager - Session created: { Id: 2, Type: DEFAULT, Logged: No, IP: 0:0:0:0:0:0:0:1:57058 } on Server port: 9933 <---> 57058
15:43:06,408 INFO [SFSWorker:Ext:4] zone.ZoneExtension - Login Type: 3
15:43:06,955 INFO [SFSWorker:Ext:4] api.SFSApi - User login: { Zone: Crypto_Game }, ( User Name: guest196, Id: 0, Priv: 0, Sess: 0:0:0:0:0:0:0:1:57058 ) , Type: WindowsEditor:1.0.3
15:43:08,066 DEBUG [SFSWorker:Ext:4] zone.ZoneExtension - ADDING VARIABLES TO THE USER
15:43:08,069 INFO [SFSWorker:Ext:4] managers.SFSRoomManager - Room created: { Zone: Crypto_Game }, [ Room: chat_room, Id: 1, Group: default, isGame: false ], type = SFSRoom
15:43:08,078 INFO [SFSWorker:Ext:4] api.SFSApi - Room joined: [ Room: chat_room, Id: 1, Group: default, isGame: false ], { Zone: Crypto_Game }, ( User Name: guest196, Id: 0, Priv: 0, Sess: 0:0:0:0:0:0:0:1:57058 ) , asSpect: false
15:43:08,079 DEBUG [SFSWorker:Ext:4] zone.ZoneExtension - User timezone -4
15:43:08,079 DEBUG [SFSWorker:Ext:4] zone.ZoneExtension - User new timezone -4
15:43:08,237 DEBUG [SFSWorker:Ext:1] zone.ZoneExtension - UNIQUE USER ID 0
15:43:08,237 DEBUG [SFSWorker:Ext:1] zone.ZoneExtension - VARIABLES COUNT 15
15:43:08,240 INFO [SFSWorker:Ext:1] zone.ZoneExtension - UserHandler guest196 action myAvatars data {"__[[REQUEST_ID]]__":"myAvatars"}[

Second login.
15:44:59,453 INFO [SocketReader] sessions.DefaultSessionManager - Session created: { Id: 3, Type: DEFAULT, Logged: No, IP: 0:0:0:0:0:0:0:1:63135 } on Server port: 9933 <---> 63135
15:44:59,714 INFO [SFSWorker:Ext:3] zone.ZoneExtension - Login Type: 3
15:45:00,610 INFO [SFSWorker:Ext:3] scala.DefLI - User already logged in. Disconnecting previous instance : ( User Name: guest196, Id: 0, Priv: 0, Sess: 0:0:0:0:0:0:0:1:57058 )
15:45:00,612 INFO [SFSWorker:Ext:3] managers.SFSRoomManager - Room removed: { Zone: Crypto_Game }, [ Room: chat_room, Id: 1, Group: default, isGame: false ], Duration: 112543
15:45:00,614 INFO [SFSWorker:Ext:3] api.SFSApi - User disconnected: { Zone: Crypto_Game }, ( User Name: guest196, Id: 0, Priv: 0, Sess: 0:0:0:0:0:0:0:1:57058 ) , SessionLen: 113659, Type: WindowsEditor:1.0.3
15:45:00,614 DEBUG [SFSWorker:Ext:2] zone.ZoneExtension - OnUserDisconnectHandler START
15:45:00,616 DEBUG [SFSWorker:Ext:2] zone.ZoneExtension - OnUserDisconnectHandler END

15:45:02,615 INFO [pool-1-thread-4] api.SFSApi - User login: { Zone: Crypto_Game }, ( User Name: guest196, Id: 1, Priv: 0, Sess: 0:0:0:0:0:0:0:1:63135 ) , Type: WindowsEditor:1.0.3
15:45:02,678 DEBUG [SFSWorker:Ext:4] zone.ZoneExtension - UNIQUE USER ID 1
15:45:02,678 DEBUG [SFSWorker:Ext:4] zone.ZoneExtension - VARIABLES COUNT 0
15:45:02,682 ERROR [SFSWorker:Ext:4] v290.ExtensionReqController - java.lang.NullPointerException:
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
Exception: java.lang.NullPointerException
Message: *** Null ***
Description: Error while handling client request in extension: { Ext: CryptoGameExtension, Type: JAVA, Lev: ZONE, { Zone: Crypto_Game }, {} }
Extension Cmd: user.myAvatars
+--- --- ---+
Stack Trace:
+--- --- ---+
com.hackembostudios.crypto_game.zone.handlers.UserHandler.handleClientRequest(UserHandler.java:52)
com.smartfoxserver.v2.extensions.SFSExtension.handleClientRequest(SFSExtension.java:208)
com.smartfoxserver.v2.controllers.v290.ExtensionReqController.processRequest(ExtensionReqController.java:174)
com.smartfoxserver.v2.controllers.v290.ExtensionReqController$1.run(ExtensionReqController.java:68)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
java.lang.Thread.run(Thread.java:748)
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

15:45:03,338 INFO [Scheduler1-thread-1] sessions.DefaultSessionManager - Session removed: { Id: 2, Type: DEFAULT, Logged: No, IP: 0:0:0:0:0:0:0:1:57058 }
15:45:03,887 DEBUG [SFSWorker:Ext:1] zone.ZoneExtension - ADDING VARIABLES TO THE USER

I think the second time it waits to remove the session before adding the variables, but for some reason it lets the user make requests, variables are added in ZoneJoinEventHandler.
User avatar
Lapo
Site Admin
Posts: 22211
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Maybe bug with force logout in 2.17.3 not present in 2.16.0

Postby Lapo » 18 Oct 2021, 13:15

Hi,
I need some clarifications...
In the logs from the first login you have this:

Code: Select all

15:43:08,079 DEBUG [SFSWorker:Ext:4] zone.ZoneExtension - User timezone -4
15:43:08,079 DEBUG [SFSWorker:Ext:4] zone.ZoneExtension - User new timezone -4
15:43:08,237 DEBUG [SFSWorker:Ext:1] zone.ZoneExtension - UNIQUE USER ID 0
15:43:08,237 DEBUG [SFSWorker:Ext:1] zone.ZoneExtension - VARIABLES COUNT 15

What is the "VARIABLES COUNT" value? The total number of User variables assigned to the User?

Then in the 2nd login you have this:

Code: Select all

15:45:02,678 DEBUG [SFSWorker:Ext:4] zone.ZoneExtension - UNIQUE USER ID 1
15:45:02,678 DEBUG [SFSWorker:Ext:4] zone.ZoneExtension - VARIABLES COUNT 0


The User id looks correct, as the new User will have a different ID than the previous one (and since you're testing locally with one User, it is expected to be == 1).
Also, there are no "User timezone" messages this time. Can you clarify why?
And finally I am not sure what to make of the "VARIABLES COUNT 0" log message, because it's not entirely clear how this works.

I think it would help if we could see the entire code you're using in both USER_LOGIN and USER_JOIN_ZONE events.

Thanks
Lapo

--

gotoAndPlay()

...addicted to flash games
User avatar
Lapo
Site Admin
Posts: 22211
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Maybe bug with force logout in 2.17.3 not present in 2.16.0

Postby Lapo » 18 Oct 2021, 13:19

To avoid posting the entire code here, you can sends us an email to our support@... mail box with a reference to this discussion.

Cheers
Lapo

--

gotoAndPlay()

...addicted to flash games
votagusvotag
Posts: 38
Joined: 07 Nov 2016, 12:26

Re: Maybe bug with force logout in 2.17.3 not present in 2.16.0

Postby votagusvotag » 18 Oct 2021, 16:31

VARIABLES COUNT is the amount of user variables at that point, since we add all variables during ZoneJoinEventHandler.
"User timezone" is a debug line inside ZoneJoinEventHandler and everything seems to indicate that the second time around, ZoneJoinEventHandler
is not executed before the cmd request.

I can't share the code since it's not mine, what I can do however is try to replicate it in a sandbox project, but as I said at the beggining, this is not a priority since we run our game in 2.16.0, but I'll do it if I can get enough free time. Thanks!

Return to “SFS2X Questions”

Who is online

Users browsing this forum: No registered users and 45 guests