java-game-server icon indicating copy to clipboard operation
java-game-server copied to clipboard
verified publisher icon menacher

onException/onDisconnect/onClose are not delivered to DefaultSessionEventHandler

Open nikolaykuz opened this issue 12 years ago • 9 comments

I have following scenario. There are 3 players in the game room, so there are 3 SessionHandlers. I shutdown one of the players. So it is SessionHandler detects that and prints onException. Then I have a code inside ServerGameManager that sends a NETWORK_MESSAGE to other clients of the same game to shutdown also. But for two other clients handlers of their SessionHandlers are never called.

public class SessionHandler extends DefaultSessionEventHandler {

    //example

    @Override
    protected void onException(Event event) {
         System.out.println("onException");
    } 

    @Override
    protected void onDisconnect(Event event) {
         System.out.println("onDisconnect");
    } 

    @Override
    protected void onClose(Event event) {
         System.out.println("onClose");
    } 

2013-04-23 15:22:07,841 [DefaultToServerHandler.java:49][ERROR]:Exception in DefaultToServerHandler class: [id: 0x03ecf7ad, /10.254.215.116:60277 => /10.254.215.116:81] EXCEPTION: java.io.IOException: An existing connection was forcibly closed by the remote host.
2013-04-23 15:22:07,842 [DefaultToServerHandler.java:60][DEBUG]:Channel 65861549 is disconnected, raising the event to session
2013-04-23 15:22:07,842 [SessionHandler.java:60][ERROR]:GAMEROOM1 PLAYER[0] onException
2013-04-23 15:22:07,842 [DefaultToServerHandler.java:78][DEBUG]:Channel 65861549 is closed and resources released
2013-04-23 15:22:07,842 [NettyTCPMessageSender.java:57][INFO]:Going to close tcp connection in class: org.menacheri.jetserver.communication.NettyTCPMessageSender
2013-04-23 15:22:07,842 [NettyTCPMessageSender.java:66][WARN]:Unable to write the Event Event [type=34, source=null, timeStamp=1366698127842] with type 34 to socket
2013-04-23 15:22:07,843 [JetlangEventDispatcher.java:260][TRACE]:Entered removeHandlersForSession for session PlayerSession [id=1player=org.menacheri.jetserver.app.impl.DefaultPlayer@d5904c89, parentGameRoom=org.evogame.server.RealGameRoom@50, protocol=null, isShuttingDown=true]
2013-04-23 15:22:07,843 [JetlangEventDispatcher.java:272][TRACE]:Going to remove 1 handlers for session: PlayerSession [id=1player=org.menacheri.jetserver.app.impl.DefaultPlayer@d5904c89, parentGameRoom=org.evogame.server.RealGameRoom@50, protocol=null, isShuttingDown=true]
2013-04-23 15:22:07,843 [JetlangEventDispatcher.java:284][TRACE]:Going to clear handlers on dispatcher org.menacheri.jetserver.event.impl.JetlangEventDispatcher@925c95
2013-04-23 15:22:07,843 [ServerGameManager.java:145][INFO]:GAMEROOM1 PLAYER[0] has disconnected!
2013-04-23 15:22:07,854 [DefaultToServerHandler.java:60][DEBUG]:Channel 476923117 is disconnected, raising the event to session
2013-04-23 15:22:07,854 [DefaultToServerHandler.java:78][DEBUG]:Channel 476923117 is closed and resources released
2013-04-23 15:22:07,854 [DefaultSessionEventHandler.java:179][DEBUG]:Received disconnect event in session. Going to close session
2013-04-23 15:22:07,854 [NettyTCPMessageSender.java:57][INFO]:Going to close tcp connection in class: org.menacheri.jetserver.communication.NettyTCPMessageSender
2013-04-23 15:22:07,854 [NettyTCPMessageSender.java:66][WARN]:Unable to write the Event Event [type=34, source=null, timeStamp=1366698127854] with type 34 to socket
2013-04-23 15:22:07,855 [JetlangEventDispatcher.java:260][TRACE]:Entered removeHandlersForSession for session PlayerSession [id=2player=org.menacheri.jetserver.app.impl.DefaultPlayer@3c452253, parentGameRoom=org.evogame.server.RealGameRoom@50, protocol=null, isShuttingDown=true]
2013-04-23 15:22:07,855 [JetlangEventDispatcher.java:272][TRACE]:Going to remove 1 handlers for session: PlayerSession [id=2player=org.menacheri.jetserver.app.impl.DefaultPlayer@3c452253, parentGameRoom=org.evogame.server.RealGameRoom@50, protocol=null, isShuttingDown=true]
2013-04-23 15:22:07,855 [JetlangEventDispatcher.java:284][TRACE]:Going to clear handlers on dispatcher org.menacheri.jetserver.event.impl.JetlangEventDispatcher@18309b0
2013-04-23 15:22:07,855 [DefaultSessionEventHandler.java:179][DEBUG]:Received disconnect event in session. Going to close session
2013-04-23 15:22:07,856 [DefaultToServerHandler.java:60][DEBUG]:Channel -395629090 is disconnected, raising the event to session
2013-04-23 15:22:07,856 [DefaultToServerHandler.java:78][DEBUG]:Channel -395629090 is closed and resources released
2013-04-23 15:22:07,856 [DefaultSessionEventHandler.java:179][DEBUG]:Received disconnect event in session. Going to close session
2013-04-23 15:22:07,856 [NettyTCPMessageSender.java:57][INFO]:Going to close tcp connection in class: org.menacheri.jetserver.communication.NettyTCPMessageSender
2013-04-23 15:22:07,856 [NettyTCPMessageSender.java:66][WARN]:Unable to write the Event Event [type=34, source=null, timeStamp=1366698127856] with type 34 to socket
2013-04-23 15:22:07,856 [JetlangEventDispatcher.java:260][TRACE]:Entered removeHandlersForSession for session PlayerSession [id=3player=org.menacheri.jetserver.app.impl.DefaultPlayer@4536c9ea, parentGameRoom=org.evogame.server.RealGameRoom@50, protocol=null, isShuttingDown=true]
2013-04-23 15:22:07,857 [JetlangEventDispatcher.java:272][TRACE]:Going to remove 1 handlers for session: PlayerSession [id=3player=org.menacheri.jetserver.app.impl.DefaultPlayer@4536c9ea, parentGameRoom=org.evogame.server.RealGameRoom@50, protocol=null, isShuttingDown=true]
2013-04-23 15:22:07,857 [JetlangEventDispatcher.java:284][TRACE]:Going to clear handlers on dispatcher org.menacheri.jetserver.event.impl.JetlangEventDispatcher@c6824e
2013-04-23 15:22:07,857 [DefaultSessionEventHandler.java:179][DEBUG]:Received disconnect event in session. Going to close session

nikolaykuz avatar Apr 23 '13 06:04 nikolaykuz

Could you provide the code you have in ServerGameManager that will disconnect the other 2 sessions. I will look into this in parallel.

menacher avatar Apr 23 '13 15:04 menacher 

Channel.close();
System.exit(0);

combinations of both

nikolaykuz avatar Apr 23 '13 15:04 nikolaykuz

any reason why you dont use playerSession.close() instead?

menacher avatar Apr 23 '13 16:04 menacher

at client side I don't have playerSession. I mean ServerGameManager sends some message to clients, upon reception they invoke

Channel.close();
System.exit(0);

nikolaykuz avatar Apr 23 '13 18:04 nikolaykuz

@nikolaykuz I haven't had time to look at this, will do so later today/tomorrow and let you know.

menacher avatar Apr 25 '13 15:04 menacher

Hopefully, in this week :)

nikolaykuz avatar Apr 28 '13 15:04 nikolaykuz

@nikolaykuz I wrote a unit test and it seems to work as expected. The subclass is getting the events. Even in your logs, I can see that the disconnect session event is reach the super class DefaultSessionEventDispatcher.

    @Test
    public void multiSessionDisconnectValidation() throws InterruptedException {
        // create necessary setup objects.
        Game game = new SimpleGame(1, "Test");
        Protocol dummyProtocol = new DummyProtocol();
        GameRoomSessionBuilder sessionBuilder = new GameRoomSessionBuilder();
        sessionBuilder.parentGame(game).gameRoomName("Zombie_ROOM_1")
                .protocol(dummyProtocol);
        CountDownLatch latch1 = new CountDownLatch(2);
        CountDownLatch latch2 = new CountDownLatch(2);
        AtomicLong counter = new AtomicLong(0l);
        Session gameRoomSession = new TestGameRoom(sessionBuilder, counter,
                latch1);
        GameRoom gameRoom = (GameRoom) gameRoomSession;
        PlayerSession playerSession = gameRoom.createPlayerSession(null);
        PlayerSession playerSession2 = gameRoom.createPlayerSession(null);
        PlayerSession playerSession3 = gameRoom.createPlayerSession(null);
        gameRoom.connectSession(playerSession);
        gameRoom.connectSession(playerSession2);
        gameRoom.connectSession(playerSession3);
        playerSession.addHandler(new SessionHandlerLatchCounter(playerSession,
                counter, latch1));
        playerSession2.addHandler(new SessionHandlerLatchCounter(playerSession2,
                counter, latch2));
        playerSession3.addHandler(new SessionHandlerLatchCounter(playerSession3,
                counter, latch2));
        // start test
        Event event1 = Events.event(null, Events.DISCONNECT);
        playerSession.onEvent(event1);// disconnect session 1.
        assertFalse(latch1.await(1000, TimeUnit.MILLISECONDS));// This is just a wait
        Event message = Events.event(null, Events.SESSION_MESSAGE);
        playerSession.onEvent(message);
        assertFalse(latch1.await(500, TimeUnit.MILLISECONDS));// Ensure that the message is not sent.
        Event event2 = Events.event(null, Events.DISCONNECT);
        Event event3 = Events.event(null, Events.DISCONNECT);
        playerSession2.onEvent(event2);
        playerSession3.onEvent(event3);

        assertTrue(latch2.await(500, TimeUnit.MILLISECONDS));
        // 1 ondisconnect(session1) + 0 onnetwork(session1) + 2 ondisconnect(session2 and 3)
        assertTrue(counter.get() == 3);
    }

I overloaded onDisconnect of class SessionHandlerLatchCounter which extends from DefaultSessionEventHandler and it received the events without issue. As you can see final assert is for counter to be 3 I couldn't try out an exact replica of your test, I will try to do that and let you know, but at first look there does not seem to be a bug.
Can you put break point in both DefaultSessionEventHandler and your SessionHandler and see why disconnect is getting invoked only on the super class and not on subclass. You will generally be able to understand by looking at which method is invoking this onDisconnect method.

b.t.w this is the relevant code from SessionHandlerLatchCounter

    @Override
    public void onNetworkMessage(NetworkEvent event) {
        counter.incrementAndGet();
        latch.countDown();
        System.out.println("invoked onNetworkMessage");
    }

    @Override
    protected void onDisconnect(Event event)
    {
        counter.incrementAndGet();
        latch.countDown();
        System.out.println("invoked onDisconnect");
        super.onDisconnect(event);
    }

menacher avatar Apr 28 '13 17:04 menacher

Hello @menacher, merge please SessionHandlerLatchCounter changes to master branch. It fails multiSessionDisconnectValidation test as of now.

tgregory avatar Jun 06 '13 10:06 tgregory

Hi @tgregory thanks for pointing it out. I will commit this tonight. Here is the relevant code from netty4 branch(I committed in this branch and forgot to commit to master)

package org.menacheri.jetserver.util;

import java.util.concurrent.CountDownLatch;
import java.util.concurrent.atomic.AtomicLong;

import org.menacheri.jetserver.app.Session;
import org.menacheri.jetserver.event.Event;
import org.menacheri.jetserver.event.NetworkEvent;
import org.menacheri.jetserver.event.impl.DefaultSessionEventHandler;

public class SessionHandlerLatchCounter extends DefaultSessionEventHandler {

    private final AtomicLong counter;
    private final CountDownLatch latch;

    public SessionHandlerLatchCounter(Session session, AtomicLong counter,
            CountDownLatch latch) {
        super(session);
        this.counter = counter;
        this.latch = latch;
    }

    @Override
    public void onNetworkMessage(NetworkEvent event) {
        counter.incrementAndGet();
        latch.countDown();
        System.out.println("invoked onNetworkMessage");
    }

    @Override
    protected void onDisconnect(Event event)
    {
        counter.incrementAndGet();
        latch.countDown();
        System.out.println("invoked onDisconnect");
        super.onDisconnect(event);
    }

    public AtomicLong getCounter() {
        return counter;
    }

    public CountDownLatch getLatch() {
        return latch;
    }

}

menacher avatar Jun 06 '13 13:06 menacher