Add diagnostics for intermittent initial login EOF

README.md

@@ -78,6 +78,8 @@ PR 的 `.gitea/workflows/verify.yml` 独立运行 `gradlew check`，不使用 Ma
 
 `smoke/local-uranium-transfer.ps1 -BundlePath <包目录>` 复制并启动两台 Uranium，然后编译仓库中的协议探针，通过实际 `ProxySessionListener` 请求从旧服切换到新服。加上 `-InstalledPlugin` 则启动已安装的 `ProxyMain`：旧服由静态配置注册，临时插件用 `Servers.register` 注册目标服，在初始落点回调读取 `ServerView`，再通过 `Players.transfer` 发起转服。默认模式使用协议探针核对 FML 重置、重新握手、世界切换包和目标连接的 Keep Alive，见 [两台 Uranium 转服记录](smoke/results/2026-09-25-local-uranium-transfer.md)。`-InstalledPlugin -ReturnToOld` 让协议探针验证旧服→新服→旧服的两次切换。`-InstalledPlugin -PrismClient` 改用本机 Prism 中的 `1.7.10` Forge 实例，要求客户端在目标服保持连接 10 秒；可同时使用 `-ReturnToOld` 验证真实客户端往返。两个真实客户端脚本都可用 `-PrismInstance <实例名>` 选择其他实例。若实例的文件夹名与启动名不同，另传 `-PrismInstanceFolder <文件夹名>`，以便准确定位并清理这次启动的客户端；`-PrismPath` 指向其他 Prism 安装位置。`smoke/local-uranium.ps1 -PrismClient` 可单独验证首次登录。这些实测仍不能替代目标整合包验收。
 
+安装包转服烟测可加 `-DebugSession`，将当前运行的会话失败路径 DEBUG 日志写入所打印运行目录的 `proxy.stdout.log`。一次间歇性初始登录 EOF 的复现实验和验证边界见 [运行记录](smoke/results/2026-09-26-initial-login-repeat.md)。
+
 ## 合成 relay 基准
 
 `benchmarks/run-relay.ps1` 比较同一 JVM、同一个本机回声后端上的直连、原始字节 relay、按帧 relay，以及安装了实际 `KeepAliveBridge` 的按帧 relay。每个连接先预热，再重复发送固定长度的合成 Minecraft 帧并读取同样长度的回声；连接数、每连接消息数、预热数、帧负载字节数、重复轮数和同时在途的消息数均可配置。`-Window 1` 是逐包等待回声；更大的窗口使用独立写线程持续发送，读线程按顺序核对回声，并用信号量限制在途消息数。基准在轮次间交替执行三种 relay，并在首尾测直连基线。输出往返吞吐、按单向传输字节计算的 MiB/s、往返延迟 p50/p95/p99、JVM GC 次数/耗时和堆已用量变化。

proxy-core/src/main/java/dev/strataproxy/core/session/Session.java

@@ -35,6 +35,8 @@ import io.netty.channel.ChannelPipeline;
 import io.netty.channel.socket.SocketChannel;
 import io.netty.channel.socket.nio.NioSocketChannel;
 import io.netty.util.ReferenceCountUtil;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import java.net.InetSocketAddress;
 import java.net.URI;
@@ -56,6 +58,7 @@ import java.util.concurrent.atomic.AtomicBoolean;
 /** Mutable session control state is confined to the frontend event loop. */
 @io.netty.channel.ChannelHandler.Sharable
 final class Session extends ChannelInboundHandlerAdapter {
+    private static final Logger LOGGER = LoggerFactory.getLogger(Session.class);
     private static final int MAX_TRANSITION_BUFFER_BYTES = ProtocolProfile.minecraft1710().maxFrameBytes();
     private static final Duration FORGE_TRANSFER_HANDSHAKE_TIMEOUT = Duration.ofSeconds(30);
     private static final Duration LOGIN_DISCONNECT_DRAIN_TIMEOUT = Duration.ofSeconds(5);
@@ -122,6 +125,8 @@ final class Session extends ChannelInboundHandlerAdapter {
             if (ctx.channel() == frontend) receiveFrontend(body);
             else receiveBackend(body);
         } catch (RuntimeException failure) {
+            LOGGER.debug("Closing session after {} frame handling failed",
+                    ctx.channel() == frontend ? "client" : "backend", failure);
             closePair();
         } finally {
             packet.release();
@@ -332,6 +337,8 @@ final class Session extends ChannelInboundHandlerAdapter {
                 return;
             }
             if (!future.isSuccess()) {
+                LOGGER.debug("Backend connection failed for player {} to {}", view.username(), selected.address(),
+                        future.cause());
                 disconnectLogin("Could not connect to the selected server.");
                 return;
             }
@@ -361,6 +368,7 @@ final class Session extends ChannelInboundHandlerAdapter {
 
     private void disconnectLogin(String reason) {
         if (closed.get() || loginDisconnectStarted) return;
+        LOGGER.debug("Login disconnect for player {}: {}", view == null ? "<unknown>" : view.username(), reason);
         loginDisconnectStarted = true;
         frontend.config().setAutoRead(false);
         resetLoginDeadline(LOGIN_DISCONNECT_DRAIN_TIMEOUT);
@@ -375,7 +383,12 @@ final class Session extends ChannelInboundHandlerAdapter {
 
     private void resetLoginDeadline(Duration timeout) {
         if (initialLoginDeadline != null) initialLoginDeadline.cancel(false);
-        initialLoginDeadline = frontend.eventLoop().schedule(this::closePair,
+        initialLoginDeadline = frontend.eventLoop().schedule(() -> {
+                    LOGGER.debug("Login phase deadline expired for player {} with backend {}; disconnect started={}",
+                            view == null ? "<unknown>" : view.username(),
+                            selected == null ? "<none>" : selected.handle().id().value(), loginDisconnectStarted);
+                    closePair();
+                },
                 timeout.toNanos(), TimeUnit.NANOSECONDS);
     }
 
@@ -384,6 +397,7 @@ final class Session extends ChannelInboundHandlerAdapter {
         ByteBuf input = packet.duplicate();
         int id = ProtocolVarInt.read(input);
         if (id == 1) { // Encryption Request means backend is not in offline mode.
+            LOGGER.debug("Backend requested encryption for player {}", view.username());
             closePair();
             return;
         }
@@ -395,17 +409,20 @@ final class Session extends ChannelInboundHandlerAdapter {
             return;
         }
         if (id != 2 || published) {
+            LOGGER.debug("Unexpected backend login packet {} for player {}", id, view.username());
             closePair();
             return;
         }
         MinecraftLoginSuccess success = MinecraftLoginSuccess.decode(packet);
         if (!success.username().equals(view.username())) {
+            LOGGER.debug("Backend login name mismatch for player {}: {}", view.username(), success.username());
             closePair();
             return;
         }
         UUID expected = owner.onlineMode() ? verifiedProfile.uuid()
                 : UUID.nameUUIDFromBytes(("OfflinePlayer:" + success.username()).getBytes(StandardCharsets.UTF_8));
         if (!expected.equals(success.playerId())) {
+            LOGGER.debug("Backend login UUID mismatch for player {}", view.username());
             closePair();
             return;
         }
@@ -1035,10 +1052,17 @@ final class Session extends ChannelInboundHandlerAdapter {
     }
 
     @Override public void channelInactive(ChannelHandlerContext ctx) {
+        if (!published && loginStart != null) {
+            LOGGER.debug("{} channel closed during initial login for player {} with backend {}",
+                    ctx.channel() == frontend ? "Client" : "Backend", loginStart.username(),
+                    selected == null ? "<none>" : selected.handle().id().value());
+        }
         if (ctx.channel() != backend || !loginDisconnectStarted) closePair();
     }
 
     @Override public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) {
+        LOGGER.debug("{} channel exception for player {}", ctx.channel() == frontend ? "Client" : "Backend",
+                view == null ? "<unknown>" : view.username(), cause);
         if (ctx.channel() == backend && loginDisconnectStarted) ctx.close();
         else closePair();
     }

smoke/local-uranium-transfer.ps1

@@ -3,6 +3,7 @@ param(
     [Parameter(Mandatory)][string]$BundlePath,
     [string]$Java8Path = 'C:\Program Files\Zulu\zulu-8\bin\java.exe',
     [switch]$InstalledPlugin,
+    [switch]$DebugSession,
     [switch]$PrismClient,
     [switch]$ReturnToOld,
     [string]$PrismInstance = '1.7.10',
@@ -12,6 +13,7 @@ param(
 
 $ErrorActionPreference = 'Stop'
 if ($PrismClient -and -not $InstalledPlugin) { throw '-PrismClient requires -InstalledPlugin' }
+if ($DebugSession -and -not $InstalledPlugin) { throw '-DebugSession requires -InstalledPlugin' }
 if ($ReturnToOld -and -not $InstalledPlugin) {
     throw '-ReturnToOld requires -InstalledPlugin'
 }
@@ -176,7 +178,22 @@ backends:
 "@ | Set-Content -LiteralPath $config -Encoding utf8
         $java = (Get-Command java.exe -ErrorAction Stop).Source
         $proxyLog = Join-Path $runDir 'proxy.stdout.log'
+        $debugJvmArgs = @()
+        if ($DebugSession) {
+            $logbackConfig = Join-Path $runDir 'logback-debug.xml'
+            @'
+<configuration>
+    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
+        <encoder><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] %logger{36} - %msg%n</pattern></encoder>
+    </appender>
+    <logger name="dev.strataproxy.core.session.Session" level="DEBUG" />
+    <root level="INFO"><appender-ref ref="CONSOLE" /></root>
+</configuration>
+'@ | Set-Content -LiteralPath $logbackConfig -Encoding utf8
+            $debugJvmArgs = @(('"-Dlogback.configurationFile={0}"' -f $logbackConfig.Replace('\', '/')))
+        }
         $proxy = Start-Process -FilePath $java -ArgumentList @(
+            $debugJvmArgs
             '-cp', ('"{0}"' -f $classpath), 'dev.strataproxy.app.ProxyMain',
             '--config', ('"{0}"' -f $config)
         ) -WindowStyle Hidden -PassThru -RedirectStandardOutput $proxyLog `

smoke/results/2026-09-26-initial-login-repeat.md

@@ -0,0 +1,15 @@
+# Initial-login EOF repeat on local Uranium
+
+Date: 2026-09-26 (Asia/Shanghai). Windows 11, local loopback, Java 25 proxy and Java 8 Uranium. The smoke starts two fresh Uranium instances, an installed proxy with the external transfer plugin, and a synthetic protocol-5 Forge client. Each run requests old → new → old and checks both backend login logs.
+
+Command per run:
+
+```powershell
+.\smoke\local-uranium-transfer.ps1 -BundlePath <Uranium bundle> -InstalledPlugin -ReturnToOld
+```
+
+At `a09fc07`, three runs passed and the fourth failed while the probe waited for the **initial Login Success** (`EOFException` at `UraniumTransferProbe.java:72`). The proxy log confirmed that the plugin's placement callback saw `[old, new]`; the old Uranium log had no player login. The failure directory is `build/local-uranium-transfer-4a2cb3e895d14a07bee6cae884c65247` in this workspace. An earlier single run also failed at the same probe line, followed by two successful runs.
+
+The next local build added failure-path DEBUG diagnostics to `Session` and an optional `-DebugSession` flag for this smoke. One validation run, six further runs with success-path DEBUG, and eight runs with only failure-path DEBUG all passed. The added diagnostics did not capture a failing session. These outcomes establish an intermittent initial-login failure in this environment; they do **not** identify a root cause or prove that the logging change fixed it.
+
+If it recurs, run the smoke with `-DebugSession` and inspect `proxy.stdout.log` in the printed run directory for the selected backend, login deadline, channel closure, and any frame-handling exception. The target Forge modpack has not been tested.