Multiple log disconnect entries for the same connection

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

Moderators: Lapo, Bax

mmilen
Posts: 298
Joined: 09 Nov 2010, 00:48
Contact:

Multiple log disconnect entries for the same connection

Postby mmilen » 25 Jan 2022, 13:55

What can cause the following entries in the log file? The disconnection is legit, all users were forced out of a room, but the room owner.
' {BridgeServer}: Disconnected user:ABOS ' this log entry is from a trace in the finally of try/catch in my event handler
addEventHandler(SFSEventType.USER_DISCONNECT, User_Disconnect_EventHandler.class);

For each disconnection, we get 1,2,3 or 4 entries, it seems random.

I have only one listener in my Zone Extension init method, and this does not happen with every user, the users are on JavaScript SFS client.


25 Jan 2022 | 01:27:54,216 | INFO | SFSWorker:Ext:4 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 109, Type: WEBSOCKET, Logged: Yes, IP: 202.220.254.251:60655 }
25 Jan 2022 | 01:27:54,216 | INFO | SFSWorker:Ext:4 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 109, Type: WEBSOCKET, Logged: Yes, IP: 202.220.254.251:60655 }
25 Jan 2022 | 01:27:54,216 | INFO | SFSWorker:Sys:8 | v2.api.SFSApi | | User disconnected: { Zone: EmaBridge_Teacher }, ( User Name: tombo2089, Id: 100, Priv: 0, Sess: 202.220.254.251:60655 ) , SessionLen: 763064, Type: JavaScript
25 Jan 2022 | 01:27:54,217 | INFO | SFSWorker:Ext:4 | v2.api.SFSApi | | User disconnected: { Zone: EmaBridge_Teacher }, ( User Name: tombo2089, Id: 100, Priv: 0, Sess: 202.220.254.251:60655 ) , SessionLen: 763065, Type: JavaScript
25 Jan 2022 | 01:27:54,217 | INFO | SFSWorker:Ext:8 | Extensions | | {BridgeServer}: Disconnected user:tombo2089
25 Jan 2022 | 01:27:54,217 | INFO | SFSWorker:Ext:7 | Extensions | | {BridgeServer}: Disconnected user:tombo2089
mmilen
Posts: 298
Joined: 09 Nov 2010, 00:48
Contact:

Re: Multiple log disconnect entries for the same connection

Postby mmilen » 25 Jan 2022, 14:28

Here is I connected a user and kicked it from the Server Admin interface. Duplicate entries in the log.

09:28:49,895 INFO [SFSWorker:Ext:1] sessions.DefaultSessionManager - Session removed: { Id: 7, Type: WEBSOCKET, Logged: Yes, IP: 192.168.80.118:60603 }
09:28:49,895 INFO [SFSWorker:Ext:1] sessions.DefaultSessionManager - Session removed: { Id: 7, Type: WEBSOCKET, Logged: Yes, IP: 192.168.80.118:60603 }
09:28:49,896 INFO [SFSWorker:Ext:1] api.SFSApi - User disconnected: { Zone: EmaBridge_Teacher }, ( User Name: Milen 12, Id: 6, Priv: 0, Sess: 192.168.80.118:60603 ) , SessionLen: 113879, Type: JavaScript
09:28:49,896 INFO [SFSWorker:Ext:1] Extensions - {BridgeServer}: Disconnected user:Milen 12
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Multiple log disconnect entries for the same connection

Postby Lapo » 26 Jan 2022, 09:48

Hi
I am not able to reproduce the problem. If I log in with a Websocket client and kick the user via AdminTool I get the expected messages, with no duplication.

It sounds like you might have a "listener leak" from previous restarts of the Extension.
I'd recommend to check your Extension code. If you're overriding the destroy() method make sure you're still invoking super.destroy() as the first line. This ensures that the parent class is called, which takes care of detaching all current listeners.

In other words your destroy method should look like this:

Code: Select all

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

   // your code ...
   // ...
}


Cheers
Lapo
--
gotoAndPlay()
...addicted to flash games
mmilen
Posts: 298
Joined: 09 Nov 2010, 00:48
Contact:

Re: Multiple log disconnect entries for the same connection

Postby mmilen » 26 Jan 2022, 12:11

That's it, the extension was reloaded a number of times. anyways to avoid it?
mmilen
Posts: 298
Joined: 09 Nov 2010, 00:48
Contact:

Re: Multiple log disconnect entries for the same connection

Postby mmilen » 26 Jan 2022, 13:02

Will this code do ( resetting all the request handlers, events, and filters ), does the order matter. Those are all added in the init method.

Code: Select all

@Override
    public void destroy() {
        removeEventHandler(SFSEventType.USER_LOGIN);
        removeEventHandler(SFSEventType.USER_JOIN_ZONE);
        removeEventHandler(SFSEventType.USER_JOIN_ROOM);
        removeEventHandler(SFSEventType.USER_DISCONNECT);
        removeEventHandler(SFSEventType.USER_LOGOUT);
        removeEventHandler(SFSEventType.USER_LEAVE_ROOM);
        removeEventHandler(SFSEventType.PLAYER_TO_SPECTATOR);
        removeEventHandler(SFSEventType.SPECTATOR_TO_PLAYER);
        removeRequestHandler(SFSVAR.EXTENSION_CONTROL_TEACHING_SESSON);
        removeRequestHandler(SFSVAR.EXTENSION_BOOT);
        removeRequestHandler(SFSVAR.EXTENSION_SEND_TO_ALL);
        removeRequestHandler(SFSVAR.EXTENSION_SEND_TO_ALL_PLAYERS);
        removeRequestHandler(SFSVAR.EXTENSION_SPEC_TO_PLAYER);
        removeRequestHandler(SFSVAR.EXTENSION_JOINTABLE);
        removeRequestHandler(SFSVAR.EXTENSION_ENDSESSION);
        removeRequestHandler(SFSVAR.EXTENSION_CREATELOBBY);
        removeRequestHandler(SFSVAR.EXTENSION_CREATESESSION);
        removeRequestHandler(SFSVAR.EXTENSION_LAG);
        getParentZone().resetSystemFilterChain();
    }
mmilen
Posts: 298
Joined: 09 Nov 2010, 00:48
Contact:

Re: Multiple log disconnect entries for the same connection

Postby mmilen » 26 Jan 2022, 14:05

Fresh server start cleared trace duplication from my

Code: Select all

addEventHandler(SFSEventType.USER_DISCONNECT, User_Disconnect_EventHandler.class);


The user is disconnected with

Code: Select all

getApi().disconnect(user.getSession());


but I still get those 3

    26 Jan 2022 | 07:42:50,702 | INFO | SFSWorker:Ext:8 | v2.api.SFSApi | | User login: { Zone: EmaBridge_Teacher }, ( User Name: Maureen, Id: 122, Priv: 0, Sess: 142.167.57.20:62691 ) , Type: JavaScript
    26 Jan 2022 | 08:01:45,933 | INFO | https-jsse-nio-8443-exec-46 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 143, Type: WEBSOCKET, Logged: Yes, IP: 142.167.57.20:62691 }
    26 Jan 2022 | 08:01:45,934 | INFO | https-jsse-nio-8443-exec-46 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 143, Type: WEBSOCKET, Logged: Yes, IP: 142.167.57.20:62691 }
    26 Jan 2022 | 08:01:45,934 | INFO | https-jsse-nio-8443-exec-46 | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 143, Type: WEBSOCKET, Logged: No, IP: 142.167.57.20:62691 }
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Multiple log disconnect entries for the same connection

Postby Lapo » 27 Jan 2022, 08:42

mmilen wrote:Will this code do ( resetting all the request handlers, events, and filters ), does the order matter. Those are all added in the init method.

Code: Select all

@Override
    public void destroy() {
        removeEventHandler(SFSEventType.USER_LOGIN);
        removeEventHandler(SFSEventType.USER_JOIN_ZONE);
        removeEventHandler(SFSEventType.USER_JOIN_ROOM);
        removeEventHandler(SFSEventType.USER_DISCONNECT);
        removeEventHandler(SFSEventType.USER_LOGOUT);
        removeEventHandler(SFSEventType.USER_LEAVE_ROOM);
        removeEventHandler(SFSEventType.PLAYER_TO_SPECTATOR);
        removeEventHandler(SFSEventType.SPECTATOR_TO_PLAYER);
        removeRequestHandler(SFSVAR.EXTENSION_CONTROL_TEACHING_SESSON);
        removeRequestHandler(SFSVAR.EXTENSION_BOOT);
        removeRequestHandler(SFSVAR.EXTENSION_SEND_TO_ALL);
        removeRequestHandler(SFSVAR.EXTENSION_SEND_TO_ALL_PLAYERS);
        removeRequestHandler(SFSVAR.EXTENSION_SPEC_TO_PLAYER);
        removeRequestHandler(SFSVAR.EXTENSION_JOINTABLE);
        removeRequestHandler(SFSVAR.EXTENSION_ENDSESSION);
        removeRequestHandler(SFSVAR.EXTENSION_CREATELOBBY);
        removeRequestHandler(SFSVAR.EXTENSION_CREATESESSION);
        removeRequestHandler(SFSVAR.EXTENSION_LAG);
        getParentZone().resetSystemFilterChain();
    }

No, instead of doing this manually I recommend using the call I suggested earlier. This way you shorten your code and you avoid issues when adding new listeners.
Lapo

--

gotoAndPlay()

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

Re: Multiple log disconnect entries for the same connection

Postby Lapo » 27 Jan 2022, 09:47

As regards the extra logging: we'll see if we can reproduce it via the server side code you have reported. In any case I don't think this is causing any issues other than adding a few bytes to the log files.

Cheers
Lapo

--

gotoAndPlay()

...addicted to flash games
mmilen
Posts: 298
Joined: 09 Nov 2010, 00:48
Contact:

Re: Multiple log disconnect entries for the same connection

Postby mmilen » 29 Jan 2022, 05:05

Thanks. I did overlook your destroy code suggestion. That might even clear the duplicate log.

Question what is a good way ( not too much over head ) to add a trace every time users' session message queue reaches a threshold.

When connecting to a Zone I have this call

Code: Select all

 user.getSession().getPacketQueue().setMaxSize(2000);
for users that monitor some 150-200 game rooms ( no more than 5-6 players in each) but every once in a while packets are dropped, which let's me think that for very brief moments this might not be enough.
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Multiple log disconnect entries for the same connection

Postby Lapo » 29 Jan 2022, 12:07

Hi,
setting to queue that high (2000) is not going to help anyone, unfortunately. It's not going to help the server which will use much more memory when users are lagging and won't help the client because queueing 1000s of messages is just delaying the problem rather than solving it.

Question what is a good way ( not too much over head ) to add a trace every time users' session message queue reaches a threshold.

I wouldn't recommend to log a message for every dropped packets, as it can go out of control very quickly if packet-dropping is something that happens on a regular basis.

You could listen to the BitSwarmEvents.PACKET_DROPPED event, but avoid to log data on every call.
I would keep a timestamp of the last event call and make sure that at least 1 second has passed before I log another message, to avoid log spamming.

Something like this:

Code: Select all

class MyListener implements IEventListener
{
   private final long COOLDOWN = 1000L;
   private long lastCall = System.currentTimeMillis();

   @Override
   void handleEvent(IEvent event)
   {
      if (event.getName().equals(BitSwarmEvents.PACKET_DROPPED))
      {
         long now = System.currentTimeMillis();
         if (now - lastCall > COOLDOWN)
         {
            ISession session (ISession) event.getParameter("session");
            
            // ...
            // etc...
            //...

            lastCall = now;
         }
         
      }
   }
}


// ...
// ...

BitSwarmEngine.getInstance().addEventListener(BitSwarmEvents.PACKET_DROPPED, new MyListener());

(I just wrote the example above in a notepad file so apologies for potential mistakes, hopefully it's correct)

Cheers
Lapo

--

gotoAndPlay()

...addicted to flash games
mmilen
Posts: 298
Joined: 09 Nov 2010, 00:48
Contact:

Re: Multiple log disconnect entries for the same connection

Postby mmilen » 29 Jan 2022, 13:36

Thanks a lot for the code sample, my cool down can be very long :). On most days there are no drops, I'm trying to see is it a user lag, or we have bad code somewhere.
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Multiple log disconnect entries for the same connection

Postby Lapo » 29 Jan 2022, 15:58

Thanks a lot for the code sample, my cool down can be very long :)


:D
Lapo

--

gotoAndPlay()

...addicted to flash games
mmilen
Posts: 298
Joined: 09 Nov 2010, 00:48
Contact:

Re: Multiple log disconnect entries for the same connection

Postby mmilen » 04 Feb 2022, 15:36

No luck catching who is dropping packets.
I have this in the core.xml : <triggerDroppedPacketEvents>true</triggerDroppedPacketEvents>

I added the listener in my zone extension Init(), which might be the wrong place. I set a user with user.getSession().getPacketQueue().setMaxSize(2); and loaded, the admin panel shows the drops but no log entries.

This is the handler class

Code: Select all

 class Drop_Packet_EventHandler implements IEventListener
    {
        private final long COOLDOWN = 500000L;
        private long lastCall = System.currentTimeMillis();

        @Override
        public void handleEvent(IEvent event)
        {
            if (event.getName().equals(BitSwarmEvents.PACKET_DROPPED))
            {
                long now = System.currentTimeMillis();
                if (now - lastCall > COOLDOWN)
                {
                    lastCall = now;
                    ISession session = (ISession) event.getParameter("session");
                    trace("Dropped Packet from IP:" + session.getAddress() + " port: " + session.getClientPort());
                }
            }
        }
    }


This is how I connect it in the init() of the extension:

Code: Select all

Drop_Packet_EventHandler networkEvtListener = new Drop_Packet_EventHandler();
          BitSwarmEngine socketEngine = BitSwarmEngine.getInstance();
          socketEngine.addEventListener(BitSwarmEvents.PACKET_DROPPED, networkEvtListener);
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Multiple log disconnect entries for the same connection

Postby Lapo » 07 Feb 2022, 15:13

Everything looks good.
However the cooldown seems way too high, at 500K ms. I would rather suggest to use 20-30 seconds as cooldown value.

Other than that it should be working.
Lapo

--

gotoAndPlay()

...addicted to flash games

Return to “SFS2X Questions”

Who is online

Users browsing this forum: No registered users and 58 guests