Network overhaul

[LevelX]

Another problem:

The client can no longer create match tables or start tournaments if it disconnects and reconnects to a server.
It only works after the first connect to a server.
Probably something related to the "SSLEngine closed already" message.

Code: Select all

ERROR 2015-08-27 16:59:08,972 Error getting table                                                                        =>[SwingWorker-pool-3-thread-4] Client.getTable
java.lang.InterruptedException
   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(Unknown Source)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
   at java.util.concurrent.LinkedBlockingQueue.take(Unknown Source)
   at org.mage.network.handlers.client.ClientMessageHandler.getTable(ClientMessageHandler.java:123)
   at org.mage.network.Client.getTable(Client.java:325)
   at mage.client.dialog.UpdateSeatsTask.doInBackground(TableWaitingDialog.java:407)
   at mage.client.dialog.UpdateSeatsTask.doInBackground(TableWaitingDialog.java:387)
   at javax.swing.SwingWorker$1.call(Unknown Source)
   at java.util.concurrent.FutureTask.run(Unknown Source)
   at javax.swing.SwingWorker.run(Unknown Source)
   at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
   at java.lang.Thread.run(Unknown Source)
ERROR 2015-08-27 16:59:54,326 Communication error                                                                        =>[nioEventLoopGroup-0-2] WriteListener.operationComplete
javax.net.ssl.SSLException: SSLEngine closed already
ERROR 2015-08-27 17:00:00,329 Error creating table                                                                       =>[AWT-EventQueue-0] Client.createTable
java.util.concurrent.RejectedExecutionException: event executor terminated
   at io.netty.util.concurrent.SingleThreadEventExecutor.reject(SingleThreadEventExecutor.java:678)
   at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(SingleThreadEventExecutor.java:270)
   at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:661)
   at io.netty.channel.DefaultChannelHandlerInvoker.invokeFlush(DefaultChannelHandlerInvoker.java:367)
   at io.netty.channel.PausableChannelEventExecutor.invokeFlush(PausableChannelEventExecutor.java:46)
   at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:557)
   at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:563)
   at org.mage.network.handlers.client.ClientMessageHandler.createTable(ClientMessageHandler.java:116)
   at org.mage.network.Client.createTable(Client.java:244)
   at mage.client.dialog.NewTableDialog.btnOKActionPerformed(NewTableDialog.java:382)
   at mage.client.dialog.NewTableDialog.access$300(NewTableDialog.java:60)
   at mage.client.dialog.NewTableDialog$4.actionPerformed(NewTableDialog.java:199)

[LevelX]

If you watch a game you can't see the game log and you can't see the game chat.
Both areas stay empty all the time.

[BetaSteward]

I've fixed all of the issues that were found so far, plus a few NPE's that I found in the server logs.

Perhaps we could get another round of testing before we go live?

BetaSteward

[LevelX]

I've updated the server to the new version called 1.4.4a4.
It's merged with the current master branch, so up-to-date.

We only need some people testing now.

[LevelX]

I've fixed some problems with DB update from server.

I will update xmage now with the network overhowl.
So the new release is 1.4.5v0 (it's like 1.4.4v6 with the new network code).

The network overhaul version worked for some test games and we will only see if it works better/good if we set it live on the public servers.

[LevelX]

Every disconnect from the server writes the following error message to the client log.

Code: Select all

ERROR 2015-09-27 20:06:15,110 Communication error =>[nioEventLoopGroup-0-4] WriteListener.operationComplete
javax.net.ssl.SSLException: SSLEngine closed already

[BetaSteward]

Every disconnect from the server writes the following error message to the client log.

Code: Select all

ERROR 2015-09-27 20:06:15,110 Communication error =>[nioEventLoopGroup-0-4] WriteListener.operationComplete
javax.net.ssl.SSLException: SSLEngine closed already

That is something that can probably be suppressed. It's not a indication that something is wrong, just that the server tried to communicate with a client that is disconnected. I'll see what can be done to eliminate it.

[LevelX]

I wonder what the <no ping> state means.

Seems to be the users that lost connection. But there is no time counter going down and the users seem to stay in the user list.

Code: Select all

31490: INFO  2015-09-27 15:43:22,674 PerHogan joined server                                                                     =>[defaultEventExecutorGroup-0-1] SessionManager.registerUser
32886: INFO  2015-09-27 15:44:18,662 USER REMOVE - PerHogan (Disconnected)  userId: a264c8ac-4815-4291-8588-efba40a0b770        =>[CALL main-59] UserManager$1.run
33122: INFO  2015-09-27 15:45:01,185 PerHogan joined server                                                                     =>[defaultEventExecutorGroup-0-0] SessionManager.registerUser
33806: INFO  2015-09-27 15:46:27,413 User PerHogan tournament started: 63233bcc-5491-47db-90c1-c695763f66e1 userId: 1f039eb0-5a1b-4da0-8129-a61d162c3023 =>[defaultEventExecutorGroup-0-3] TableController.startTournament
44323: INFO  2015-09-27 15:54:11,294 GAME started 94554612-0200-4bd8-b5e1-8d8c83980992 [] PerHogan - Unraveler                  =>[CALL main-59] TableController.startGame
46715: INFO  2015-09-27 16:00:03,785 GAME END  gameId: 94554612-0200-4bd8-b5e1-8d8c83980992 [Unraveler => L] - [PerHogan => W]  =>[GAME 94554612-0200-4bd8-b5e1-8d8c83980992] GameImpl.play
47017: INFO  2015-09-27 16:01:03,801 GAME started 37542272-7db8-4747-8f58-69ed8e3025fd [] PerHogan - Unraveler                  =>[GAME 94554612-0200-4bd8-b5e1-8d8c83980992] TableController.startGame
49910: INFO  2015-09-27 16:11:29,917 GAME END  gameId: 37542272-7db8-4747-8f58-69ed8e3025fd [PerHogan => L] - [Unraveler => W]  =>[GAME 37542272-7db8-4747-8f58-69ed8e3025fd] GameImpl.play
55817: INFO  2015-09-27 16:12:45,391 USER REMOVE - PerHogan (Disconnected)  userId: 1f039eb0-5a1b-4da0-8129-a61d162c3023        =>[CALL main-663] UserManager$1.run
55858: INFO  2015-09-27 16:13:00,264 PerHogan joined server                                                                     =>[defaultEventExecutorGroup-0-3] SessionManager.registerUser

[LevelX]

Found this error in the log:

Code: Select all

FATAL 2015-09-27 16:28:48,317 Send info about player not joined yet:                                                     =>[pool-135-thread-1] GameController$3.run
java.lang.NullPointerException
   at mage.server.game.GameController.sendInfoAboutPlayersNotJoinedYet(GameController.java:378)
   at mage.server.game.GameController.access$2000(GameController.java:99)
   at mage.server.game.GameController$3.run(GameController.java:283)
   at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
   at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
   at java.lang.Thread.run(Thread.java:745)

I added a check for the session object that causes the error if it was null.
Looks like this now (if else and logger statements are added)

Code: Select all

                       
Session session = SessionManager.getInstance().getSession(user.getSessionId());
if (session != null) {
  ChatManager.getInstance().broadcast(chatId, user, session.getPingInfo() + " is pending to join the game", MessageColor.BLUE, true, ChatMessage.MessageType.STATUS);
} else {
  logger.debug("Player " + player.getName() + " - not possible to get session  gameId: " + game.getId());
}

[LevelX]

Found this error in the server log:

Code: Select all

ERROR 2015-09-27 16:13:00,807 Communications error                                                                       =>[nioEventLoopGroup-2-0] ServerExceptionHandler.exceptionCaught
java.lang.NullPointerException
   at mage.server.ServerMain.joinTournamentTable(ServerMain.java:307)
   at org.mage.network.messages.requests.JoinTournamentTableRequest.handleMessage(JoinTournamentTableRequest.java:35)
   at org.mage.network.handlers.server.ServerRequestHandler.messageReceived(ServerRequestHandler.java:25)
   at org.mage.network.handlers.server.ServerRequestHandler.messageReceived(ServerRequestHandler.java:14)
   at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
   at io.netty.channel.ChannelHandlerInvokerUtil.invokeChannelReadNow(ChannelHandlerInvokerUtil.java:84)
   at io.netty.channel.DefaultChannelHandlerInvoker$7.run(DefaultChannelHandlerInvoker.java:158)
   at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:46)
   at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
   at io.netty.util.internal.chmv8.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1412)
   at io.netty.util.internal.chmv8.ForkJoinTask.doExec(ForkJoinTask.java:280)
   at io.netty.util.internal.chmv8.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:877)
   at io.netty.util.internal.chmv8.ForkJoinPool.scan(ForkJoinPool.java:1706)
   at io.netty.util.internal.chmv8.ForkJoinPool.runWorker(ForkJoinPool.java:1661)
   at io.netty.util.internal.chmv8.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:126)

[LevelX]

I reverted the server back to 1.4.4v6 because there were severe problems with 1.4.5v0 on woogerworks server.

Here's link to the server log from the time 1.4.5v0 was running on the server.
https://drive.google.com/file/d/0B69TXnHQFJayZjNEcF9Ub2dVRkk/view?usp=sharing

I guess we have to analyse the errors and fix if possible and after that to retry.

The log includes:
746 [user] joined server messages
481 USER REMOVE - [user] (Disconnected)
130 MATCH started
194 GAME started
180 GAME END
3993 [id: 0x9c1df5c5, /0:0:0:0:0:0:0:0:17171] RECEIVED: [id:

3045 Communications error - io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: 6a6273317b
107 Communications error - java.io.IOException: Connection reset by peer
1939 Communication error - javax.net.ssl.SSLException: SSLEngine closed already
311 User update exception: jnts - java.lang.NullPointerException at mage.server.util.SystemUtil.getDateDiff(SystemUtil.java:180)
130 Send info about player not joined yet java.lang.NullPointerException at mage.server.game.GameController.sendInfoAboutPlayersNotJoinedYet(GameController.java:378)
156 endSession: unexpected reason ConnectingOtherInstance
115 Session not found sessionId
738 Your session expired:

[LevelX]

This is repeated very often. Probably freezing client table panel update.

Code: Select all

FATAL 2015-09-27 16:42:40,599 User update exception: jnts - java.lang.NullPointerException                               =>[pool-2-thread-1] GamesRoomImpl.update
java.lang.NullPointerException
   at mage.server.util.SystemUtil.getDateDiff(SystemUtil.java:180)
   at mage.server.User.getSecondsDisconnected(User.java:182)
   at mage.server.User.getDisconnectDuration(User.java:166)
   at mage.server.User.getGameInfo(User.java:514)
   at mage.server.game.GamesRoomImpl.update(GamesRoomImpl.java:120)
   at mage.server.game.GamesRoomImpl.access$000(GamesRoomImpl.java:67)
   at mage.server.game.GamesRoomImpl$1.run(GamesRoomImpl.java:82)
   at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
   at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
   at java.lang.Thread.run(Thread.java:745)

User related lines of the log (cut at the end):

Code: Select all

34558: INFO  2015-09-27 15:48:16,576 jnts joined server                                                                         =>[defaultEventExecutorGroup-0-3] SessionManager.registerUser
37854: INFO  2015-09-27 15:50:31,562 USER REMOVE - jnts (Disconnected)  userId: 9846c951-c415-4f65-ab59-19e1343b677c            =>[CALL main-417] UserManager$1.run
39706: INFO  2015-09-27 15:50:44,792 jnts joined server                                                                         =>[defaultEventExecutorGroup-0-2] SessionManager.registerUser
40716: INFO  2015-09-27 15:50:52,186 Disconnecting another user instance: jnts                                                  =>[defaultEventExecutorGroup-0-3] Session.registerUserHandling
40718: INFO  2015-09-27 15:50:52,187 jnts joined server                                                                         =>[defaultEventExecutorGroup-0-3] SessionManager.registerUser
49519: INFO  2015-09-27 16:09:47,415 Disconnecting another user instance: jnts                                                  =>[defaultEventExecutorGroup-0-3] Session.registerUserHandling
49520: INFO  2015-09-27 16:09:47,416 jnts joined server                                                                         =>[defaultEventExecutorGroup-0-3] SessionManager.registerUser
50528: INFO  2015-09-27 16:12:32,833 Disconnecting another user instance: jnts                                                  =>[defaultEventExecutorGroup-0-1] Session.registerUserHandling
50530: INFO  2015-09-27 16:12:32,834 jnts joined server                                                                         =>[defaultEventExecutorGroup-0-1] SessionManager.registerUser
50754: INFO  2015-09-27 16:12:32,861 USER REMOVE - jnts (Disconnected)  userId: 322fe89c-0795-4fed-8563-ed266d401029            =>[CALL main-732] UserManager$1.run
51770: INFO  2015-09-27 16:12:32,900 jnts joined server                                                                         =>[defaultEventExecutorGroup-0-1] SessionManager.registerUser
51809: INFO  2015-09-27 16:12:32,905 USER REMOVE - jnts (Disconnected)  userId: 0e6d2d57-bcc9-4bf8-b98d-38091a67b4d5            =>[CALL main-717] UserManager$1.run
57255: INFO  2015-09-27 16:18:53,890 jnts joined server                                                                         =>[defaultEventExecutorGroup-0-3] SessionManager.registerUser
58825: INFO  2015-09-27 16:24:34,734 User jnts tournament started: 39f73beb-0ae6-46c1-b0f9-146a4387241f userId: e8599436-374d-4c59-8a5e-22fe5977b6e4 =>[defaultEventExecutorGroup-0-3] TableController.startTournament
58833: INFO  2015-09-27 16:24:35,192 User jnts draft started: 125e83af-6400-4930-b440-16e41e9355d9 userId: e8599436-374d-4c59-8a5e-22fe5977b6e4 =>[CALL main-663] TableController.startDraft
64555: INFO  2015-09-27 16:40:11,417 User jnts tournament started: d6623e38-08ec-461f-87d2-4f8e793af497 userId: e8599436-374d-4c59-8a5e-22fe5977b6e4 =>[defaultEventExecutorGroup-0-3] TableController.startTournament
65230: FATAL 2015-09-27 16:42:40,599 User update exception: jnts - java.lang.NullPointerException                               =>[pool-2-thread-1] GamesRoomImpl.update
65246: FATAL 2015-09-27 16:42:42,600 User update exception: jnts - java.lang.NullPointerException                               =>[pool-2-thread-1] GamesRoomImpl.update
65263: FATAL 2015-09-27 16:42:44,598 User update exception: jnts - java.lang.NullPointerException                               =>[pool-2-thread-1] GamesRoomImpl.update
65303: FATAL 2015-09-27 16:42:46,598 User update exception: jnts - java.lang.NullPointerException                               =>[pool-2-thread-1] GamesRoomImpl.update
65354: FATAL 2015-09-27 16:42:48,599 User update exception: jnts - java.lang.NullPointerException                               =>[pool-2-thread-1] GamesRoomImpl.update
65371: FATAL 2015-09-27 16:42:50,598 User update exception: jnts - java.lang.NullPointerException                              =>[pool-2-thread-1] GamesRoomImpl.update

[BetaSteward]

Hmmmm. I guess that's one way to get some more beta testing done.

I'll take a look at the logs and see if we can figure out what improvements can be made.

Did you get any feedback from users on what their experience was like? ex: laggy, features not working, dropped connections, etc.

[LevelX]

Did you get any feedback from users on what their experience was like? ex: laggy, features not working, dropped connections, etc.

I played mayself a sealed match and hand absolutely no problems (no lag, all was working as expected).
All this time also nobody complained about such problems in the chat. About 100-120 users were connected to the server.

At some point later I was disconnected and was not able to reconnect directly.
Some minutes later I could reconnect but only about 50 users are still connected. And 2 minutes later the UI froze and I had to cancel the xmage client java process. So I decided to revert to the previous release.