Capture early Uranium login stall evidence

README.md

@@ -78,7 +78,7 @@ 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)。
+安装包转服烟测可加 `-DebugSession`，在本次复制的 Uranium 配置中开启登录阶段日志，并将代理会话的连接、登录写入和失败路径 DEBUG 日志写入所打印运行目录的 `proxy.stdout.log`。初次登录 EOF 的复现实验见 [运行记录](smoke/results/2026-09-26-initial-login-repeat.md)；增强日志后捕获的 Uranium 登录停滞及源码假设见 [登录停滞记录](smoke/results/2026-09-26-uranium-login-stalls.md)。
 
 ## 合成 relay 基准
 

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

@@ -345,6 +345,8 @@ final class Session extends ChannelInboundHandlerAdapter {
                 return;
             }
             backendConnected = true;
+            LOGGER.debug("Initial backend TCP connection established for player {} to {}",
+                    view.username(), selected.address());
             ByteBuf handshakeBody = null;
             ByteBuf loginBody;
             try {
@@ -359,7 +361,15 @@ final class Session extends ChannelInboundHandlerAdapter {
                 return;
             }
             backend.write(handshakeBody);
-            backend.writeAndFlush(loginBody);
+            backend.writeAndFlush(loginBody).addListener(write -> {
+                if (write.isSuccess()) {
+                    LOGGER.debug("Initial backend login frames flushed for player {} to {}",
+                            view.username(), selected.address());
+                } else {
+                    LOGGER.debug("Initial backend login write failed for player {} to {}",
+                            view.username(), selected.address(), write.cause());
+                }
+            });
         });
     }
 
@@ -662,6 +672,8 @@ final class Session extends ChannelInboundHandlerAdapter {
         }
         TransferAttempt attempt = new TransferAttempt(target, result, relay);
         transfer = attempt;
+        LOGGER.debug("Starting replacement backend connection for player {} to {}",
+                view.username(), target.address());
         attempt.candidate = new TransferCandidate(identity.playerId(), view.username(), new TransferCandidate.Listener() {
             @Override public void ready(TransferCandidate candidate) { candidateReady(attempt); }
             @Override public void failed(TransferCandidate candidate, String reason) { failTransfer(attempt, reason); }
@@ -685,7 +697,14 @@ final class Session extends ChannelInboundHandlerAdapter {
             attempt.channel = connect.channel();
             connect.addListener(future -> {
                 if (attempt.finished || closed.get()) { connect.channel().close(); return; }
-                if (!future.isSuccess()) { failTransfer(attempt, "could not connect to replacement backend"); return; }
+                if (!future.isSuccess()) {
+                    LOGGER.debug("Replacement backend connection failed for player {} to {}",
+                            view.username(), attempt.target.address(), future.cause());
+                    failTransfer(attempt, "could not connect to replacement backend");
+                    return;
+                }
+                LOGGER.debug("Replacement backend TCP connection established for player {} to {}",
+                        view.username(), attempt.target.address());
                 writeBackendLogin(connect.channel());
             });
         } catch (RuntimeException failure) {
@@ -709,6 +728,13 @@ final class Session extends ChannelInboundHandlerAdapter {
         ByteBuf loginBody = new LoginStart(view.username()).encode(frontend.alloc(), ProtocolProfile.minecraft1710());
         channel.write(handshakeBody);
         channel.writeAndFlush(loginBody).addListener(write -> {
+            if (write.isSuccess()) {
+                LOGGER.debug("Replacement backend login frames flushed for player {} to {}",
+                        view.username(), channel.remoteAddress());
+            } else {
+                LOGGER.debug("Replacement backend login write failed for player {}",
+                        view.username(), write.cause());
+            }
             if (!write.isSuccess() && transfer != null && transfer.channel == channel) {
                 failTransfer(transfer, "could not write replacement backend login");
             }
@@ -979,6 +1005,10 @@ final class Session extends ChannelInboundHandlerAdapter {
 
     private void failTransfer(TransferAttempt attempt, String reason) {
         if (attempt.finished) return;
+        LOGGER.debug("Replacement backend failed for player {} to {}: {}; channel registered={}, active={}",
+                view.username(), attempt.target.address(), reason,
+                attempt.channel != null && attempt.channel.isRegistered(),
+                attempt.channel != null && attempt.channel.isActive());
         attempt.finished = true;
         attempt.failureReason = reason;
         if (attempt.channel != null) attempt.channel.close();

smoke/UraniumTransferProbe.java

@@ -69,7 +69,19 @@ public final class UraniumTransferProbe {
                 out.writeByte(0);
                 string(out, "NettyProbe");
             }));
-            require(packetId(read(client)) == 2, "missing LOGIN success");
+            byte[] loginFrame = read(client);
+            int loginPacketId = packetId(loginFrame);
+            if (loginPacketId == 0) {
+                DataInputStream reason = new DataInputStream(new ByteArrayInputStream(loginFrame));
+                varInt(reason);
+                int length = varInt(reason);
+                require(length >= 0 && length <= 32767 && length <= reason.available(),
+                        "invalid LOGIN disconnect reason length " + length);
+                byte[] json = new byte[length];
+                reason.readFully(json);
+                throw new AssertionError("LOGIN disconnected: " + new String(json, StandardCharsets.UTF_8));
+            }
+            require(loginPacketId == 2, "missing LOGIN success; packet id=" + loginPacketId);
 
             int firstHellos = 0;
             while (true) {

smoke/local-uranium-transfer.ps1

@@ -101,6 +101,23 @@ online-mode=false
 level-name=world
 motd=StrataProxy Uranium transfer smoke
 "@ | Set-Content -LiteralPath (Join-Path $directory 'server.properties') -Encoding utf8
+    if ($DebugSession) {
+        $cauldronConfig = Join-Path $directory 'cauldron.yml'
+        if (Test-Path -LiteralPath $cauldronConfig) {
+            $contents = Get-Content -LiteralPath $cauldronConfig -Raw
+            if ($contents -match '(?m)^[ \t]*user-login:[ \t]*(?:true|false)[ \t]*$') {
+                $contents = $contents -replace '(?m)^([ \t]*user-login:[ \t]*)(?:true|false)[ \t]*$', '${1}true'
+            } elseif ($contents -match '(?m)^logging:[ \t]*$') {
+                $contents = $contents -replace '(?m)^logging:[ \t]*$', "logging:`n  user-login: true"
+            } else {
+                $contents += "`nlogging:`n  user-login: true`n"
+            }
+            Set-Content -LiteralPath $cauldronConfig -Value $contents -Encoding utf8
+        } else {
+            "logging:`n  user-login: true" |
+                Set-Content -LiteralPath $cauldronConfig -Encoding utf8
+        }
+    }
     $info = [System.Diagnostics.ProcessStartInfo]::new()
     $info.FileName = $Java8Path
     $info.WorkingDirectory = $directory

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

@@ -21,3 +21,7 @@ Another focused test found that the login-stage deadline itself closed the clien
 A separate focused test found another raw-EOF path: a backend that accepted the connection and read the login packets could close before Login Success. The proxy now sends `Selected server closed during login.` to the client and releases the pending session. The test failed with EOF before the change and passed afterward. The earlier intermittent case still has no captured backend-close event, so this remains a behavior fix rather than a root-cause claim.
 
 After this change, `./gradlew.bat check --no-daemon` passed and one installed-plugin Uranium roundtrip with `-DebugSession` passed both transfers and backend-log checks. Runtime evidence is in `build/local-uranium-transfer-a41f1bcb359a40ed93629076084753c1` (ignored local directory). One passing run does not establish that the intermittent initial-login failure is gone.
+
+Uranium source review narrows what its logs can prove. `NetHandlerLoginServer.processLoginStart` logs `Login attempt` only when `cauldron.yml` enables `logging.user-login` (default `false`). `ServerConfigurationManager.initializeConnectionToPlayer` writes `logged in with entity id` only after the Forge handshake completes. `NetHandlerHandshakeTCP.onDisconnect` is empty, so an early handshake close may leave no player-specific line. Therefore, the earlier missing `logged in` line proves only that the player did not finish joining; it does not prove that Uranium never accepted the TCP connection or Login Start.
+
+The `-DebugSession` smoke option now enables `logging.user-login` in each copied Uranium configuration, alongside the proxy session DEBUG logger. A fresh installed-plugin roundtrip passed; both backend logs contain `Login attempt`, `Received profile`, and completed-login lines, and both generated `cauldron.yml` files show `user-login: true`. Its local evidence directory is `build/local-uranium-transfer-4ff529545a3d45359a9b4d70efadfc56`. The source bundle is not edited.

smoke/results/2026-09-26-uranium-login-stalls.md

@@ -0,0 +1,14 @@
+# Uranium login stalls with early-stage diagnostics
+
+Date: 2026-09-26 (Asia/Shanghai). The installed StrataProxy plugin smoke used two fresh local Uranium instances, `-ReturnToOld`, and `-DebugSession`. The debug option enabled Uranium `logging.user-login` in the copied servers and proxy session DEBUG logs. The source bundle was not changed.
+
+## Observed failures
+
+- In `build/local-uranium-transfer-f05fc625bcb34716bd597807fd159ef9`, the initial login to `old` completed. The plugin's later transfer to `new` failed after 15 seconds with `backend login timed out`. The `new` server had printed `Done` and had `user-login: true`, but its log contained no `Login attempt`. This run predates proxy-side candidate connection and write markers, so it does not show whether the candidate TCP connection completed.
+- In `build/local-uranium-transfer-cd4885b1e7894cd7bd28b2b5e4146556`, the proxy logged an initial TCP connection to `old` at 03:39:45.217 and a successful Netty login-frame write at 03:39:45.220. Uranium had `user-login: true` but printed no `Login attempt`. The proxy's 15-second login deadline then sent `Login timed out.` to the client. Three immediately preceding runs of the same smoke passed. Netty's successful write means the socket write completed; it does not prove that Uranium decoded or processed Login Start.
+
+## Source-based explanation to test
+
+In Uranium's `NetworkSystem.addLanEndpoint`, `networkManagers.add(networkmanager)` runs inside the Netty channel initializer, before the manager is added to the pipeline and before `NetworkManager.channelActive` assigns its `channel`. Concurrently, `NetworkSystem.networkTick` removes any manager for which `isChannelOpen()` is false; that method returns false while `channel` is null. The tick can therefore remove a newly accepted manager before it becomes active. `C00Handshake.hasPriority()` is true, so the handshake can still be handled on Netty I/O, while Login Start is queued for `processReceivedPackets()` on the server tick. If the manager has already been removed from the tick list, Login Start can wait indefinitely without a `Login attempt` line. `NetHandlerHandshakeTCP.onDisconnect` is empty, so an early close may also leave no player-specific log.
+
+This interleaving matches both observed stalls, but no failing run directly recorded removal of a manager before `channelActive`. It is a hypothesis, not a proven root cause. The next discriminating check is a disposable Uranium build that records manager registration, activation, and removal by connection, or registers the manager only after activation and compares repeated runs under the same smoke conditions.