Add network diagnostics logging and migrate to tinylog (Card-Forge#10004)

MostCromulent · claude · web-flow · commit b166223d69ed · 2026-03-07T10:14:13.000Z
Co-authored-by: Claude Opus 4.6 &lt;noreply@anthropic.com&gt;
diff --git a/forge-game/src/main/java/forge/trackable/TrackableTypes.java b/forge-game/src/main/java/forge/trackable/TrackableTypes.java
@@ -5,6 +5,7 @@
 import java.util.Map.Entry;
 import java.util.Set;
 
+import org.tinylog.Logger;
 import com.google.common.collect.Lists;
 import com.google.common.collect.Maps;
 import com.google.common.collect.Sets;
@@ -119,7 +120,7 @@ protected void copyChangedProps(TrackableObject from, TrackableObject to, Tracka
                             }
                         }
                     } catch (IndexOutOfBoundsException e) {
-                        System.err.println("got an IndexOutOfBoundsException, trying to continue ...");
+                        Logger.warn("IndexOutOfBoundsException in TrackableTypes, trying to continue");
                     }
                 }
             }
diff --git a/forge-gui/src/main/java/forge/gamemodes/net/CompatibleObjectDecoder.java b/forge-gui/src/main/java/forge/gamemodes/net/CompatibleObjectDecoder.java
@@ -7,6 +7,7 @@
 import io.netty.handler.codec.LengthFieldBasedFrameDecoder;
 import io.netty.handler.codec.serialization.ClassResolver;
 import net.jpountz.lz4.LZ4BlockInputStream;
+import org.tinylog.Logger;
 
 import java.io.ObjectInputStream;
 import java.io.StreamCorruptedException;
@@ -25,10 +26,13 @@ public CompatibleObjectDecoder(int maxObjectSize, ClassResolver classResolver) {
 
     @Override
     protected Object decode(ChannelHandlerContext ctx, ByteBuf in) throws Exception {
+        int frameStart = in.readerIndex();
         ByteBuf frame = (ByteBuf)super.decode(ctx, in);
         if (frame == null) {
             return null;
         }
+        int frameSize = frame.readableBytes();
+        long startMs = System.currentTimeMillis();
         ObjectInputStream ois = GuiBase.hasPropertyConfig() ?
                 new ObjectInputStream(new LZ4BlockInputStream(new ByteBufInputStream(frame, true))):
                     new CObjectInputStream(new LZ4BlockInputStream(new ByteBufInputStream(frame, true)),this.classResolver);
@@ -37,11 +41,17 @@ protected Object decode(ChannelHandlerContext ctx, ByteBuf in) throws Exception
         try {
             var5 = ois.readObject();
         } catch (StreamCorruptedException e) {
-            System.err.printf("Version Mismatch: %s%n", e.getMessage());
+            Logger.error("Version Mismatch: {}", e.getMessage());
         } finally {
             ois.close();
         }
 
+        long elapsed = System.currentTimeMillis() - startMs;
+        if (elapsed > 50 || frameSize > 20_000) {
+            Logger.info("Decoded {} in {} ms ({} bytes compressed)",
+                    var5 != null ? var5.getClass().getSimpleName() : "null", elapsed, frameSize);
+        }
+
         return var5;
     }
 }
diff --git a/forge-gui/src/main/java/forge/gamemodes/net/CompatibleObjectEncoder.java b/forge-gui/src/main/java/forge/gamemodes/net/CompatibleObjectEncoder.java
@@ -6,6 +6,7 @@
 import io.netty.channel.ChannelHandlerContext;
 import io.netty.handler.codec.MessageToByteEncoder;
 import net.jpountz.lz4.LZ4BlockOutputStream;
+import org.tinylog.Logger;
 
 import java.io.ObjectOutputStream;
 import java.io.Serializable;
@@ -33,6 +34,10 @@ protected void encode(ChannelHandlerContext ctx, Serializable msg, ByteBuf out)
         }
 
         int endIdx = out.writerIndex();
-        out.setInt(startIdx, endIdx - startIdx - 4);
+        int msgSize = endIdx - startIdx - 4;
+        out.setInt(startIdx, msgSize);
+        if (msgSize > 20_000) {
+            Logger.info("Encoded {} bytes (compressed) for {}", msgSize, msg.getClass().getSimpleName());
+        }
     }
 }
diff --git a/forge-gui/src/main/java/forge/gamemodes/net/GameProtocolHandler.java b/forge-gui/src/main/java/forge/gamemodes/net/GameProtocolHandler.java
@@ -7,6 +7,7 @@
 import forge.localinstance.skin.FSkinProp;
 import io.netty.channel.ChannelHandlerContext;
 import io.netty.channel.ChannelInboundHandlerAdapter;
+import org.tinylog.Logger;
 
 import java.io.Serializable;
 import java.lang.reflect.InvocationTargetException;
@@ -28,7 +29,7 @@ protected GameProtocolHandler(final boolean runInEdt) {
     @Override
     public final void channelRead(final ChannelHandlerContext ctx, final Object msg) {
         final String[] catchedError = {""};
-        System.out.println("Received: " + msg);
+        Logger.info("Received: {}", msg);
         if (msg instanceof ReplyEvent) {
             final ReplyEvent event = (ReplyEvent) msg;
             getReplyPool(ctx).complete(event.getIndex(), event.getReply());
@@ -41,28 +42,36 @@ public final void channelRead(final ChannelHandlerContext ctx, final Object msg)
             if (method == null) {
                 //throw new IllegalStateException(String.format("Method %s not found", protocolMethod.name()));
                 catchedError[0] += String.format("IllegalStateException: Method %s not found (GameProtocolHandler.java Line 43)\n", protocolMethod.name());
-                System.err.printf("Method %s not found%n", protocolMethod.name());
+                Logger.error("Method {} not found", protocolMethod.name());
             }
 
             final Object[] args = event.getObjects();
             protocolMethod.checkArgs(args);
 
             final Object toInvoke = getToInvoke(ctx);
 
-            // Pre-call actions
+            // Pre-call actions (runs on IO thread — blocks all subsequent messages)
+            final long beforeCallStart = System.currentTimeMillis();
             beforeCall(protocolMethod, args);
+            final long beforeCallMs = System.currentTimeMillis() - beforeCallStart;
+            if (beforeCallMs > 50) {
+                Logger.info("beforeCall({}) took {} ms on IO thread", methodName, beforeCallMs);
+            }
 
             final Class<?> returnType = protocolMethod.getReturnType();
+            final long receiveTimeMs = System.currentTimeMillis();
             final Runnable toRun = () -> {
+                final long startMs = System.currentTimeMillis();
+                final long queueDelayMs = startMs - receiveTimeMs;
                 if (returnType.equals(Void.TYPE)) {
                     try {
                         method.invoke(toInvoke, args);
                     } catch (final IllegalAccessException | IllegalArgumentException e) {
-                        System.err.printf("Unknown protocol method %s with %d args%n", methodName, args == null ? 0 : args.length);
+                        Logger.error("Unknown protocol method {} with {} args", methodName, args == null ? 0 : args.length);
                     } catch (final InvocationTargetException e) {
                         //throw new RuntimeException(e.getTargetException());
                         catchedError[0] += (String.format("RuntimeException: %s (GameProtocolHandler.java Line 65)\n", e.getTargetException().toString()));
-                        System.err.println(e.getTargetException().toString());
+                        Logger.error("InvocationTargetException: {}", e.getTargetException().toString());
                     }
                 } else {
                     Serializable reply = null;
@@ -72,18 +81,22 @@ public final void channelRead(final ChannelHandlerContext ctx, final Object msg)
                             protocolMethod.checkReturnValue(theReply);
                             reply = (Serializable) theReply;
                         } else if (theReply != null) {
-                            System.err.printf("Non-serializable return type %s for method %s, returning null%n", returnType.getName(), methodName);
+                            Logger.error("Non-serializable return type {} for method {}, returning null", returnType.getName(), methodName);
                         }
                     } catch (final IllegalAccessException | IllegalArgumentException e) {
-                        System.err.printf("Unknown protocol method %s with %d args, replying with null%n", methodName, args == null ? 0 : args.length);
+                        Logger.error("Unknown protocol method {} with {} args, replying with null", methodName, args == null ? 0 : args.length);
                     } catch (final NullPointerException | InvocationTargetException e) {
                         //throw new RuntimeException(e.getTargetException());
                         catchedError[0] += e.toString();
                         SOptionPane.showMessageDialog(catchedError[0], "Error", FSkinProp.ICO_WARNING);
-                        System.err.println(e.toString());
+                        Logger.error("Exception in protocol method {}: {}", methodName, e.toString());
                     }
                     getRemote(ctx).send(new ReplyEvent(event.getId(), reply));
                 }
+                final long elapsed = System.currentTimeMillis() - startMs;
+                if (queueDelayMs > 50 || elapsed > 50) {
+                    Logger.info("Protocol {} processed in {} ms (queued {} ms)", methodName, elapsed, queueDelayMs);
+                }
             };
 
             if (runInEdt) {
diff --git a/forge-gui/src/main/java/forge/gamemodes/net/ProtocolMethod.java b/forge-gui/src/main/java/forge/gamemodes/net/ProtocolMethod.java
@@ -11,6 +11,7 @@
 import forge.game.spellability.SpellAbilityView;
 import forge.gamemodes.match.NextGameDecision;
 import forge.gui.GuiBase;
+import org.tinylog.Logger;
 import forge.gui.interfaces.IGuiGame;
 import forge.interfaces.IGameController;
 import forge.localinstance.skin.FSkinProp;
@@ -131,7 +132,7 @@ public Method getMethod() {
             }
             return candidate;
         } catch (final NoSuchMethodException | SecurityException e) {
-            System.err.printf("Warning: class contains no accessible method named %s%n", name());
+            Logger.warn("Class contains no accessible method named {}", name());
             return getMethodNoArgs();
         }
     }
@@ -140,7 +141,7 @@ private Method getMethodNoArgs() {
         try {
             return mode.toInvoke.getMethod(name(), (Class<?>[]) null);
         } catch (final NoSuchMethodException | SecurityException e) {
-            System.err.printf("Warning: class contains no accessible arg-less method named %s%n", name());
+            Logger.warn("Class contains no accessible arg-less method named {}", name());
             return null;
         }
     }
@@ -161,12 +162,11 @@ public void checkArgs(final Object[] args) {
                 final Class<?> type = this.args[iArg];
                 if (!ReflectionUtil.isInstance(arg, type)) {
                     //throw new InternalError(String.format("Protocol method %s: illegal argument (%d) of type %s, %s expected", name(), iArg, arg.getClass().getName(), type.getName()));
-                    System.err.printf("InternalError: Protocol method %s: illegal argument (%d) of type %s, %s expected (ProtocolMethod.java)%n", name(), iArg, arg.getClass().getName(), type.getName());
+                    Logger.error("Protocol method {}: illegal argument ({}) of type {}, {} expected", name(), iArg, arg.getClass().getName(), type.getName());
                 }
             }
         } catch (Exception e) {
-            System.out.println(e.getMessage());
-            e.printStackTrace();
+            Logger.error(e, "Error checking args for protocol method {}", name());
         }
     }
 
@@ -181,7 +181,7 @@ public void checkReturnValue(final Object value) {
         }
         if (!ReflectionUtil.isInstance(value, returnType)) {
             //throw new IllegalStateException(String.format("Protocol method %s: illegal return object type %s returned by client, expected %s", name(), value.getClass().getName(), getReturnType().getName()));
-            System.err.printf("IllegalStateException: Protocol method %s: illegal return object type %s returned by client, expected %s  (ProtocolMethod.java)%n", name(), value.getClass().getName(), getReturnType().getName());
+            Logger.error("Protocol method {}: illegal return type {} from client, expected {}", name(), value.getClass().getName(), getReturnType().getName());
         }
     }
 }
diff --git a/forge-gui/src/main/java/forge/gamemodes/net/client/FGameClient.java b/forge-gui/src/main/java/forge/gamemodes/net/client/FGameClient.java
@@ -6,6 +6,7 @@
 import forge.gamemodes.net.CompatibleObjectEncoder;
 import forge.gamemodes.net.ReplyPool;
 import forge.gamemodes.net.event.*;
+import org.tinylog.Logger;
 import forge.gui.interfaces.IGuiGame;
 import forge.interfaces.ILobbyListener;
 import io.netty.bootstrap.Bootstrap;
@@ -72,15 +73,13 @@ public void initChannel(final SocketChannel ch) throws Exception {
                 try {
                     ch.sync();
                 } catch (final InterruptedException e) {
-                    System.out.println(e.getMessage());
-                    e.printStackTrace();
+                    Logger.error(e, "Client channel interrupted");
                 } finally {
                     group.shutdownGracefully();
                 }
             }).start();
         } catch (final InterruptedException e) {
-            System.out.println(e.getMessage());
-            e.printStackTrace();
+            Logger.error(e, "Client connect interrupted");
         }
     }
 
@@ -94,7 +93,7 @@ public void send(final NetEvent event) {
         if (disconnectSimulated) {
             return;
         }
-        System.out.println("Client sent " + event);
+        Logger.info("Client sent {}", event);
         channel.writeAndFlush(event);
     }
 
@@ -104,7 +103,7 @@ public void send(final NetEvent event) {
      * will detect the silence and close the connection.
      */
     public void simulateDisconnect() {
-        System.out.println("[simulateDisconnect] Suspending all network writes.");
+        Logger.info("[simulateDisconnect] Suspending all network writes.");
         disconnectSimulated = true;
         // Remove the IdleStateHandler to stop heartbeats, and add an outbound
         // handler that drops ALL writes (including game replies that bypass
@@ -115,11 +114,11 @@ public void simulateDisconnect() {
             channel.pipeline().addFirst("writeBlocker", new ChannelOutboundHandlerAdapter() {
                 @Override
                 public void write(ChannelHandlerContext ctx, Object msg, ChannelPromise promise) {
-                    System.out.println("[writeBlocker] Dropped: " + msg.getClass().getSimpleName());
+                    Logger.info("[writeBlocker] Dropped: {}", msg.getClass().getSimpleName());
                     promise.setSuccess();
                 }
             });
-            System.out.println("[simulateDisconnect] Pipeline modified: IdleStateHandler removed, writeBlocker added.");
+            Logger.info("[simulateDisconnect] Pipeline modified: IdleStateHandler removed, writeBlocker added.");
         });
     }
 
diff --git a/forge-gui/src/main/java/forge/gamemodes/net/client/GameClientHandler.java b/forge-gui/src/main/java/forge/gamemodes/net/client/GameClientHandler.java
@@ -8,6 +8,7 @@
 import forge.gamemodes.match.LobbySlot;
 import forge.gamemodes.net.GameProtocolHandler;
 import forge.gamemodes.net.IRemote;
+import org.tinylog.Logger;
 import forge.gamemodes.net.ProtocolMethod;
 import forge.gamemodes.net.ReplyPool;
 import forge.gamemodes.net.event.LoginEvent;
@@ -301,7 +302,7 @@ else if (obj instanceof PlayerZoneUpdates) {
     private void replicatePlayerView(final PlayerView newPlayerView) {
         PlayerView existingPlayerView = tracker.getObj(TrackableTypes.PlayerViewType, newPlayerView.getId());
         existingPlayerView.copyChangedProps(newPlayerView);
-        System.err.println("replicated PlayerView properties - " + existingPlayerView.toString());
+        Logger.info("Replicated PlayerView properties - {}", existingPlayerView);
     }
 
     @Override
diff --git a/forge-gui/src/main/java/forge/gamemodes/net/server/FServerManager.java b/forge-gui/src/main/java/forge/gamemodes/net/server/FServerManager.java
diff --git a/forge-gui/src/main/java/forge/gamemodes/net/server/NetGuiGame.java b/forge-gui/src/main/java/forge/gamemodes/net/server/NetGuiGame.java
diff --git a/forge-gui/src/main/java/forge/gamemodes/net/server/RemoteClient.java b/forge-gui/src/main/java/forge/gamemodes/net/server/RemoteClient.java

Original file line number	Diff line number	Diff line change
`@@ -5,6 +5,7 @@`
`5`	`5`	`import java.util.Map.Entry;`
`6`	`6`	`import java.util.Set;`
`7`	`7`
	`8`	`+import org.tinylog.Logger;`
`8`	`9`	`import com.google.common.collect.Lists;`
`9`	`10`	`import com.google.common.collect.Maps;`
`10`	`11`	`import com.google.common.collect.Sets;`
`@@ -119,7 +120,7 @@ protected void copyChangedProps(TrackableObject from, TrackableObject to, Tracka`
`119`	`120`	`}`
`120`	`121`	`}`
`121`	`122`	`} catch (IndexOutOfBoundsException e) {`
`122`		`- System.err.println("got an IndexOutOfBoundsException, trying to continue ...");`
	`123`	`+ Logger.warn("IndexOutOfBoundsException in TrackableTypes, trying to continue");`
`123`	`124`	`}`
`124`	`125`	`}`
`125`	`126`	`}`
Original file line number	Diff line number	Diff line change
`@@ -6,6 +6,7 @@`
`6`	`6`	`import io.netty.channel.ChannelHandlerContext;`
`7`	`7`	`import io.netty.handler.codec.MessageToByteEncoder;`
`8`	`8`	`import net.jpountz.lz4.LZ4BlockOutputStream;`
	`9`	`+import org.tinylog.Logger;`
`9`	`10`
`10`	`11`	`import java.io.ObjectOutputStream;`
`11`	`12`	`import java.io.Serializable;`
`@@ -33,6 +34,10 @@ protected void encode(ChannelHandlerContext ctx, Serializable msg, ByteBuf out)`
`33`	`34`	`}`
`34`	`35`
`35`	`36`	`int endIdx = out.writerIndex();`
`36`		`- out.setInt(startIdx, endIdx - startIdx - 4);`
	`37`	`+ int msgSize = endIdx - startIdx - 4;`
	`38`	`+ out.setInt(startIdx, msgSize);`
	`39`	`+ if (msgSize > 20_000) {`
	`40`	`+ Logger.info("Encoded {} bytes (compressed) for {}", msgSize, msg.getClass().getSimpleName());`
	`41`	`+ }`
`37`	`42`	`}`
`38`	`43`	`}`
Original file line number	Diff line number	Diff line change
`@@ -11,6 +11,7 @@`
`11`	`11`	`import forge.game.spellability.SpellAbilityView;`
`12`	`12`	`import forge.gamemodes.match.NextGameDecision;`
`13`	`13`	`import forge.gui.GuiBase;`
	`14`	`+import org.tinylog.Logger;`
`14`	`15`	`import forge.gui.interfaces.IGuiGame;`
`15`	`16`	`import forge.interfaces.IGameController;`
`16`	`17`	`import forge.localinstance.skin.FSkinProp;`
`@@ -131,7 +132,7 @@ public Method getMethod() {`
`131`	`132`	`}`
`132`	`133`	`return candidate;`
`133`	`134`	`} catch (final NoSuchMethodException \| SecurityException e) {`
`134`		`- System.err.printf("Warning: class contains no accessible method named %s%n", name());`
	`135`	`+ Logger.warn("Class contains no accessible method named {}", name());`
`135`	`136`	`return getMethodNoArgs();`
`136`	`137`	`}`
`137`	`138`	`}`
`@@ -140,7 +141,7 @@ private Method getMethodNoArgs() {`
`140`	`141`	`try {`
`141`	`142`	`return mode.toInvoke.getMethod(name(), (Class<?>[]) null);`
`142`	`143`	`} catch (final NoSuchMethodException \| SecurityException e) {`
`143`		`- System.err.printf("Warning: class contains no accessible arg-less method named %s%n", name());`
	`144`	`+ Logger.warn("Class contains no accessible arg-less method named {}", name());`
`144`	`145`	`return null;`
`145`	`146`	`}`
`146`	`147`	`}`
`@@ -161,12 +162,11 @@ public void checkArgs(final Object[] args) {`
`161`	`162`	`final Class<?> type = this.args[iArg];`
`162`	`163`	`if (!ReflectionUtil.isInstance(arg, type)) {`
`163`	`164`	`//throw new InternalError(String.format("Protocol method %s: illegal argument (%d) of type %s, %s expected", name(), iArg, arg.getClass().getName(), type.getName()));`
`164`		`- System.err.printf("InternalError: Protocol method %s: illegal argument (%d) of type %s, %s expected (ProtocolMethod.java)%n", name(), iArg, arg.getClass().getName(), type.getName());`
	`165`	`+ Logger.error("Protocol method {}: illegal argument ({}) of type {}, {} expected", name(), iArg, arg.getClass().getName(), type.getName());`
`165`	`166`	`}`
`166`	`167`	`}`
`167`	`168`	`} catch (Exception e) {`
`168`		`- System.out.println(e.getMessage());`
`169`		`- e.printStackTrace();`
	`169`	`+ Logger.error(e, "Error checking args for protocol method {}", name());`
`170`	`170`	`}`
`171`	`171`	`}`
`172`	`172`
`@@ -181,7 +181,7 @@ public void checkReturnValue(final Object value) {`
`181`	`181`	`}`
`182`	`182`	`if (!ReflectionUtil.isInstance(value, returnType)) {`
`183`	`183`	`//throw new IllegalStateException(String.format("Protocol method %s: illegal return object type %s returned by client, expected %s", name(), value.getClass().getName(), getReturnType().getName()));`
`184`		`- System.err.printf("IllegalStateException: Protocol method %s: illegal return object type %s returned by client, expected %s (ProtocolMethod.java)%n", name(), value.getClass().getName(), getReturnType().getName());`
	`184`	`+ Logger.error("Protocol method {}: illegal return type {} from client, expected {}", name(), value.getClass().getName(), getReturnType().getName());`
`185`	`185`	`}`
`186`	`186`	`}`
`187`	`187`	`}`