Diconnection Because of Idle

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

Moderators: Lapo, Bax

User avatar
ekrem5353
Posts: 118
Joined: 10 Dec 2015, 15:50

Diconnection Because of Idle

Postby ekrem5353 » 05 Mar 2019, 08:53

Hi,

We have 6 games ( all board games ). all on the same SmartFox 2.13.4 instance. Six zones. In all our games clients continuously sends test extensions in order to not become idle. We have been getting this complaint since for ever but we were saying internet is bad. In our zones Overriden user maximum idle time is 60. and clients sends extension request every 6 seconds so they should not be idle. My boss said to me I was in the all of games but I got disconnected from only one of them why? I looked at logs it say User *** disconnected because of IDLE I said to my boss it must be because of bad internet. He said I was in the other games too why I did not get disconnected from other games if internet is bad? I said I do not know. And another problem sometimes in a second hundreds of users gets disconnected and log says disconnected because of unknown this does not happen that often but I can not answer that either.

Thanks
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Diconnection Because of Idle

Postby Lapo » 05 Mar 2019, 09:21

Hi,
this is something I've said multiple times when these issues occur. The server never disconnects anyone, unless the idle timer is triggered.
If you run a test in a local environment and connect any number of clients you will see no one ever gets disconnected. The only change you have online is that you're over the internet and your packets go through many different network devices, which add many more potential causes for disconnection.

With this said, there could be other issues that may interfere with the server, such as too many resources used (CPU, RAM, network) which may cause unexpected behaviors.

Have you been monitoring those resources?
Have you checked the bandwidth usage (via your hosting provider monitor) during those times in which mass disconnections happen?
Have you inspected the server logs to see if there are any recurring errors that may affect the server activity?

If you can give us more details we'll be happy to provide as many suggestions as possible.
Thanks
Lapo
--
gotoAndPlay()
...addicted to flash games
User avatar
ekrem5353
Posts: 118
Joined: 10 Dec 2015, 15:50

Re: Diconnection Because of Idle

Postby ekrem5353 » 06 Apr 2019, 16:06

This does not happen at busy times. usually smartfox uses 2% of cpu little ram I do not think this is resource related. we keep logs at mysql db. We write user counts at every minute. total user count changes around 10 to 30 in every minute. This is when everything is normal. But sometimes ones in a week or couple of times in a week this occur which is user count drops from like 2500 to 1800 in a minute ( not exact numbers when around afternoon user counts less. around 1500 something so number is lower.... we send mail to ourselves when user count drops more then hundred in a minute). I check the logs. I write trace at disconnect event it says disconnection reason unknown these users quickly reconnect again users count goes back to same number in couple of minutes again. Not all of them though some of them gets mad and dont come back. And we have client side constantly send testextension request so they dont disconnect because of timeout. so in the logs as soon as these users get disconnected lots of this logs follows


31 Mar 2019 | 17:08:51,898 | WARN | SFSWorker:Ext:46 | controllers.v290.ExtensionReqController | | com.smartfoxserver.v2.exceptions.SFSExtensionException: Extension Request refused. Sender is not a User: { Id: 574104, Type: DEFAULT, Logged: No, IP: 188.3.237.106:62371 }
com.smartfoxserver.v2.controllers.v290.ExtensionReqController.processRequest(ExtensionReqController.java:93)
com.smartfoxserver.v2.controllers.v290.ExtensionReqController$1.run(ExtensionReqController.java:68)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)



**********************But first we get hundreds of this******************************************


31 Mar 2019 | 17:08:33,278 | INFO | pool-1-thread-4 | v2.api.SFSApi | | User disconnected: { Zone: CanakKelime101 }, ( User Name: 86331, Id: 460352, Priv: 1, Sess: 217.131.79.123:20139 ) , SessionLen: 1267153, Type: Unity
31 Mar 2019 | 17:08:33,322 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 574093, Type: DEFAULT, Logged: No, IP: 88.224.143.24:49064 }
31 Mar 2019 | 17:08:33,361 | INFO | pool-1-thread-1 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 569493, Type: DEFAULT, Logged: Yes, IP: 78.177.111.88:58087 }
31 Mar 2019 | 17:08:33,361 | INFO | pool-1-thread-1 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey }, ( User Name: 126912, Id: 458310, Priv: 1, Sess: 78.177.111.88:58087 ) , SessionLen: 2855288, Type: Flash
31 Mar 2019 | 17:08:33,384 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574142, Type: DEFAULT, Logged: No, IP: 151.135.216.14:25408 } on Server port: 9933 <---> 25408
31 Mar 2019 | 17:08:33,394 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574143, Type: DEFAULT, Logged: No, IP: 78.190.230.250:4594 } on Server port: 9933 <---> 4594
31 Mar 2019 | 17:08:33,420 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 574143, Type: DEFAULT, Logged: No, IP: 78.190.230.250:4594 }
31 Mar 2019 | 17:08:33,436 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574144, Type: DEFAULT, Logged: No, IP: 78.190.230.250:2879 } on Server port: 9933 <---> 2879
31 Mar 2019 | 17:08:33,436 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 574090, Type: DEFAULT, Logged: No, IP: 78.180.57.85:12411 }
31 Mar 2019 | 17:08:33,446 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574145, Type: DEFAULT, Logged: No, IP: 46.196.84.226:10773 } on Server port: 9933 <---> 10773
31 Mar 2019 | 17:08:33,477 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 574145, Type: DEFAULT, Logged: No, IP: 46.196.84.226:10773 }
31 Mar 2019 | 17:08:33,507 | INFO | pool-1-thread-4 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 571917, Type: DEFAULT, Logged: Yes, IP: 77.190.131.183:60833 }
31 Mar 2019 | 17:08:33,508 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574146, Type: DEFAULT, Logged: No, IP: 217.131.79.123:20244 } on Server port: 9933 <---> 20244
31 Mar 2019 | 17:08:33,508 | INFO | pool-1-thread-4 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey }, ( User Name: 22252, Id: 460268, Priv: 1, Sess: 77.190.131.183:60833 ) , SessionLen: 1331557, Type: Flash
31 Mar 2019 | 17:08:33,518 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574147, Type: DEFAULT, Logged: No, IP: 46.196.84.226:11794 } on Server port: 9933 <---> 11794
31 Mar 2019 | 17:08:33,739 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574148, Type: DEFAULT, Logged: No, IP: 78.179.218.70:49597 } on Server port: 9933 <---> 49597
31 Mar 2019 | 17:08:33,750 | INFO | pool-1-thread-4 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 564486, Type: DEFAULT, Logged: Yes, IP: 88.230.6.212:11869 }
31 Mar 2019 | 17:08:33,751 | INFO | pool-1-thread-4 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey101 }, ( User Name: 121737, Id: 454293, Priv: 1, Sess: 88.230.6.212:11869 ) , SessionLen: 5900665, Type: Flash
31 Mar 2019 | 17:08:33,790 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 574148, Type: DEFAULT, Logged: No, IP: 78.179.218.70:49597 }
31 Mar 2019 | 17:08:33,808 | INFO | pool-1-thread-2 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 571499, Type: DEFAULT, Logged: Yes, IP: 78.175.48.241:47116 }
31 Mar 2019 | 17:08:33,809 | INFO | pool-1-thread-2 | v2.api.SFSApi | | User disconnected: { Zone: IhaleliBatak }, ( User Name: 22800, Id: 459927, Priv: 1, Sess: 78.175.48.241:47116 ) , SessionLen: 1566414, Type: Flash
31 Mar 2019 | 17:08:33,823 | INFO | pool-1-thread-1 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 566071, Type: DEFAULT, Logged: Yes, IP: 88.234.118.145:55732 }
31 Mar 2019 | 17:08:33,825 | INFO | pool-1-thread-1 | entities.managers.SFSRoomManager | | Room removed: { Zone: CanakOkey101 }, [ SFSGame: OYZ13, Id: 87681, Group: oyunZade, public: true, minPlayers: 4 ], Duration: 4307725
31 Mar 2019 | 17:08:33,825 | INFO | pool-1-thread-1 | entities.managers.SFSRoomManager | | Room removed: { Zone: CanakOkey101 }, [ SFSGame: OYZ36, Id: 87722, Group: oyunZade, public: true, minPlayers: 4 ], Duration: 4153332
31 Mar 2019 | 17:08:33,826 | INFO | pool-1-thread-1 | entities.managers.SFSRoomManager | | Room removed: { Zone: CanakOkey101 }, [ SFSGame: OYZ5, Id: 87886, Group: oyunZade, public: true, minPlayers: 4 ], Duration: 3461377
31 Mar 2019 | 17:08:33,826 | INFO | pool-1-thread-1 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey101 }, ( User Name: 111064, Id: 455578, Priv: 1, Sess: 88.234.118.145:55732 ) , SessionLen: 4898314, Type: Unity
31 Mar 2019 | 17:08:33,842 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574149, Type: DEFAULT, Logged: No, IP: 78.179.218.70:49598 } on Server port: 9933 <---> 49598
31 Mar 2019 | 17:08:33,852 | INFO | pool-1-thread-1 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 560141, Type: DEFAULT, Logged: Yes, IP: 78.165.181.132:59895 }
31 Mar 2019 | 17:08:33,853 | INFO | pool-1-thread-1 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey101 }, ( User Name: 19948, Id: 451386, Priv: 1, Sess: 78.165.181.132:59895 ) , SessionLen: 8452025, Type: Flash
31 Mar 2019 | 17:08:34,124 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574150, Type: DEFAULT, Logged: No, IP: 85.96.217.155:49212 } on Server port: 9933 <---> 49212
31 Mar 2019 | 17:08:34,125 | INFO | pool-1-thread-4 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 567356, Type: DEFAULT, Logged: Yes, IP: 176.43.194.179:11475 }
31 Mar 2019 | 17:08:34,126 | INFO | pool-1-thread-4 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey }, ( User Name: 4105, Id: 456578, Priv: 1, Sess: 176.43.194.179:11475 ) , SessionLen: 4184740, Type: Flash
31 Mar 2019 | 17:08:34,171 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 574150, Type: DEFAULT, Logged: No, IP: 85.96.217.155:49212 }
31 Mar 2019 | 17:08:34,196 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574151, Type: DEFAULT, Logged: No, IP: 85.96.217.155:47950 } on Server port: 9933 <---> 47950
31 Mar 2019 | 17:08:34,248 | INFO | qtp1532756055-796461 | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574152, Type: WEBSOCKET, Logged: No, IP: 176.33.253.59 } on Server port: 8843 <---> 33108
31 Mar 2019 | 17:08:34,258 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 570336, Type: DEFAULT, Logged: Yes, IP: 94.54.77.206:49295 }
31 Mar 2019 | 17:08:34,259 | INFO | SFSWorker:Sys:1 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey101 }, ( User Name: 34774, Id: 458993, Priv: 1, Sess: 94.54.77.206:49295 ) , SessionLen: 2345598, Type: Flash
31 Mar 2019 | 17:08:34,344 | INFO | pool-1-thread-4 | Extensions | | {Kelime101Extension}: next player 121747 is being disconnected
31 Mar 2019 | 17:08:34,344 | INFO | pool-1-thread-4 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 572866, Type: DEFAULT, Logged: Yes, IP: 5.24.45.3:37676 }
31 Mar 2019 | 17:08:34,345 | INFO | pool-1-thread-4 | v2.api.SFSApi | | User disconnected: { Zone: CanakKelime101 }, ( User Name: 121747, Id: 461055, Priv: 1, Sess: 5.24.45.3:37676 ) , SessionLen: 747467, Type: Unity
31 Mar 2019 | 17:08:34,359 | INFO | pool-1-thread-2 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 572895, Type: DEFAULT, Logged: Yes, IP: 46.154.189.81:5836 }
31 Mar 2019 | 17:08:34,360 | INFO | pool-1-thread-2 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey101 }, ( User Name: 112632, Id: 461083, Priv: 1, Sess: 46.154.189.81:5836 ) , SessionLen: 734288, Type: Unity
31 Mar 2019 | 17:08:34,478 | INFO | pool-1-thread-1 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 573108, Type: DEFAULT, Logged: Yes, IP: 188.3.194.171:46583 }
31 Mar 2019 | 17:08:34,478 | INFO | pool-1-thread-1 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey101 }, ( User Name: 86211, Id: 461251, Priv: 1, Sess: 188.3.194.171:46583 ) , SessionLen: 622063, Type: Unity
31 Mar 2019 | 17:08:34,607 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 573585, Type: DEFAULT, Logged: Yes, IP: 94.235.32.59:8538 }
31 Mar 2019 | 17:08:34,608 | INFO | SFSWorker:Sys:2 | v2.api.SFSApi | | User disconnected: { Zone: Pisti }, ( User Name: 148176, Id: 461635, Priv: 1, Sess: 94.235.32.59:8538 ) , SessionLen: 331366, Type: Unity
31 Mar 2019 | 17:08:34,612 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574153, Type: DEFAULT, Logged: No, IP: 88.234.118.145:59433 } on Server port: 9933 <---> 59433
31 Mar 2019 | 17:08:34,654 | INFO | pool-1-thread-1 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 565551, Type: DEFAULT, Logged: Yes, IP: 78.182.170.232:45744 }
31 Mar 2019 | 17:08:34,655 | INFO | pool-1-thread-1 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey }, ( User Name: 132980, Id: 455163, Priv: 1, Sess: 78.182.170.232:45744 ) , SessionLen: 5215841, Type: Unity
31 Mar 2019 | 17:08:34,696 | INFO | pool-1-thread-2 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 569042, Type: DEFAULT, Logged: Yes, IP: 176.88.16.1:22559 }
31 Mar 2019 | 17:08:34,696 | INFO | pool-1-thread-2 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey101 }, ( User Name: 122976, Id: 457955, Priv: 1, Sess: 176.88.16.1:22559 ) , SessionLen: 3128849, Type: Unity
31 Mar 2019 | 17:08:34,720 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574154, Type: DEFAULT, Logged: No, IP: 5.24.45.3:37609 } on Server port: 9933 <---> 37609
31 Mar 2019 | 17:08:34,772 | INFO | pool-1-thread-1 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 571963, Type: DEFAULT, Logged: Yes, IP: 94.55.134.110:61623 }
31 Mar 2019 | 17:08:34,773 | INFO | pool-1-thread-1 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey101 }, ( User Name: 101922, Id: 460310, Priv: 1, Sess: 94.55.134.110:61623 ) , SessionLen: 1299283, Type: Flash
31 Mar 2019 | 17:08:34,787 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574155, Type: DEFAULT, Logged: No, IP: 188.3.194.171:45819 } on Server port: 9933 <---> 45819
31 Mar 2019 | 17:08:34,797 | INFO | pool-1-thread-4 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 572194, Type: DEFAULT, Logged: Yes, IP: 81.215.89.88:57355 }
31 Mar 2019 | 17:08:34,798 | INFO | pool-1-thread-4 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey }, ( User Name: 4712, Id: 460506, Priv: 1, Sess: 81.215.89.88:57355 ) , SessionLen: 1173701, Type: Flash
31 Mar 2019 | 17:08:34,859 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574156, Type: DEFAULT, Logged: No, IP: 46.154.189.81:5780 } on Server port: 9933 <---> 5780
31 Mar 2019 | 17:08:34,879 | INFO | SFSWorker:Sys:3 | v2.api.SFSApi | | Room joined: [ Room: sultanZade, Id: 8, Group: sultanZade, isGame: false ], { Zone: Pisti }, ( User Name: 258199, Id: 461952, Priv: 1, Sess: 159.146.74.29:51752 ) , asSpect: false
31 Mar 2019 | 17:08:34,900 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574157, Type: DEFAULT, Logged: No, IP: 176.88.16.1:22460 } on Server port: 9933 <---> 22460
31 Mar 2019 | 17:08:34,931 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 574158, Type: DEFAULT, Logged: No, IP: 78.182.170.232:36008 } on Server port: 9933 <---> 36008
31 Mar 2019 | 17:08:35,027 | INFO | pool-1-thread-3 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 573597, Type: DEFAULT, Logged: Yes, IP: 88.232.169.87:5426 }
31 Mar 2019 | 17:08:35,028 | INFO | pool-1-thread-3 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey101 }, ( User Name: 3735, Id: 461641, Priv: 1, Sess: 88.232.169.87:5426 ) , SessionLen: 330298, Type: Flash
31 Mar 2019 | 17:08:35,042 | INFO | pool-1-thread-2 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 573449, Type: DEFAULT, Logged: Yes, IP: 81.213.176.125:50084 }
31 Mar 2019 | 17:08:35,043 | INFO | pool-1-thread-2 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey101 }, ( User Name: 12946, Id: 461530, Priv: 1, Sess: 81.213.176.125:50084 ) , SessionLen: 399351, Type: Flash
31 Mar 2019 | 17:08:35,051 | INFO | pool-1-thread-2 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 561841, Type: DEFAULT, Logged: Yes, IP: 88.236.237.88:53241 }
31 Mar 2019 | 17:08:35,051 | INFO | pool-1-thread-2 | v2.api.SFSApi | | User disconnected: { Zone: CanakOkey }, ( User Name: 132706, Id: 452267, Priv: 1, Sess: 88.236.237.88:53241 ) , SessionLen: 7569027, Type: Flash
31 Mar 2019 | 17:08**********************************

it goes on like this depending on how much users get disconnected



Then logs goes back to normal


Thanks
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Diconnection Because of Idle

Postby Lapo » 08 Apr 2019, 07:43

Hi,
the fact that it doesn't happen in busy times makes it even more difficult to understand and suggests an external network issue.
If the problem happened constantly when the server is super busy there might be an issue with maybe SFS2X being too overloaded. Even if it's not using all the CPU/RAM there could be issues with blocking calls in Extension code slowing down the server threads etc...

However if this is happening randomly, as you explained, I would first investigate the state of the network.
What hosting provider are you using?

As regards this error:
31 Mar 2019 | 17:08:51,898 | WARN | SFSWorker:Ext:46 | controllers.v290.ExtensionReqController | | com.smartfoxserver.v2.exceptions.SFSExtensionException: Extension Request refused. Sender is not a User:


This is expected. When there's a mass-disconnection, the server is probably still processing requests from those clients. Because processing happens in a multi-threaded fashion all requests that are handled a microsecond after the disconnection will fail because the user is no longer logged in, and therefore they are dropped.

Thanks
Lapo

--

gotoAndPlay()

...addicted to flash games

Return to “SFS2X Questions”

Who is online

Users browsing this forum: No registered users and 74 guests