Multiple log disconnect entries for the same connection
Multiple log disconnect entries for the same connection
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
' {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
Re: Multiple log disconnect entries for the same connection
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
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
Re: Multiple log disconnect entries for the same connection
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:
Cheers
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
Re: Multiple log disconnect entries for the same connection
That's it, the extension was reloaded a number of times. anyways to avoid it?
Re: Multiple log disconnect entries for the same connection
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();
}
Re: Multiple log disconnect entries for the same connection
Fresh server start cleared trace duplication from my
The user is disconnected with
but I still get those 3
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 }
Re: Multiple log disconnect entries for the same connection
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.
Re: Multiple log disconnect entries for the same connection
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
Cheers
Re: Multiple log disconnect entries for the same connection
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 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.
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);
Re: Multiple log disconnect entries for the same connection
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.
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:
(I just wrote the example above in a notepad file so apologies for potential mistakes, hopefully it's correct)
Cheers
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
Re: Multiple log disconnect entries for the same connection
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.
Re: Multiple log disconnect entries for the same connection
Thanks a lot for the code sample, my cool down can be very long
Re: Multiple log disconnect entries for the same connection
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
This is how I connect it in the init() of the extension:
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);
Re: Multiple log disconnect entries for the same connection
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.
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.
Who is online
Users browsing this forum: No registered users and 58 guests