ClientConfigurationConnectionEvents.READY event is fired too early
Sollace opened this issue ยท 9 comments
There's something funky with QSL's version of the fabric networking. Specifically the ClientConfigurationConnectionEvents.READY event is being fired before packets registered for this stage are finished being sent
For example, Fabwork has this for synchronising mod ids between clients:
Client Code:
The server sets up and sends the consent at configure on their end:
Server Code:
Log Output showing events are reversed:
Expected Behaviour
The packet is added to the configuration and sent to the client at the start of the configuration phase. Using the normal fabric, this packet is received and handled, then at the end when it completes the configuration phase, the READY event is striggered.
Observed Behaviour
The READY event is somehow being fired BEFORE the packet arrives on the client. Either before it's sent/lands, or before it is handled the event is fired.
The end result is that Fabwork attempts verification before the server's response is processed, and it subsequently kills the connection.
Steps To Reproduce
To reproduce, you need https://modrinth.com/mod/unicopia on a 1.20.4 server and client, and only to attempt joining the server with the client.
Logs
Also here are the logs sent to me by the user who reported the issue. I've only really tested with Fabric and Fabric/SynatraConnector/Forge on 1.20.4, and with Quilt on 1.20.1 so I know it works there. Seems for now it's only Quilt 1.20.4 that has this issue.
Client Log: https://mclo.gs/zWOg6Z8
"Server" Client Log: https://mclo.gs/I1bUAVK
Client Log (quilt downgraded 0.24.0 and earlier QFAPI as a test): https://mclo.gs/5RDpvEE
"Server" Client Log: https://mclo.gs/jyE6sKs
Also their PrismMC profile: https://cdn.discordapp.com/attachments/182492149001093120/1231636768198234132/1.20.4_Testing.zip?ex=6637ae20&is=66253920&hm=bc0e004cbefc402db4847b61d0120bc0df32128382833daa5275b14d3e1e0c8d&
Hello, I'm the user in question and I'm still running into this. I updated QFAPI to the latest version and am still getting an error.
Local LAN game as per usual, logs from both:
Server "Client": https://mclo.gs/qSgHVwM
My Client: https://mclo.gs/N4y2MFm
Server
[17:47:43] [Netty Server IO #7/INFO]: Sending mod list to coppercore[/**.**.**.**:50685]
[17:47:43] [Netty Server IO #7/INFO]: Got mod list from coppercore[/**.**.**.**:50685]: [unicopia, unicopia-blockus] (2)
[17:47:43] [Netty Server IO #7/INFO]: Connection succeeded with 2 syncronised mod(s) [unicopia, unicopia-blockus]
[17:47:43] [Server thread/INFO]: coppercore[/**.**.**.**:50685] logged in with entity id 6580 at (-356.5, 64.0, 658.5)
[17:47:43] [Server thread/INFO]: coppercore joined the game
[17:47:43] [Render thread/INFO]: [CHAT] coppercore joined the game
Client
[17:47:42] [Netty Client IO #0/ERROR]: Server is missing required mod(s). Remove these from your client to join this server. [unicopia, unicopia-blockus]
[17:47:42] [Netty Client IO #0/INFO]: Connection would fail with message 'translation{key='fabwork.error.server_missing_mods', args=[unicopia, unicopia-blockus]}' but was allowed anyway due to configured rules.
[17:47:42] [Netty Client IO #0/INFO]: Got mod list from server: [unicopia, unicopia-blockus] (2)
Also resource loading is totally screwed up on both the client and server. That's the issue that kind of got this whole discussion started, but seeing that it's present on the server, and according to the logs the join wasn't actually prevented (setting was configured to allow the user to join anyway) I'm starting to wonder if that is an unrelated problem.
I still think it's a problem with networking on the client because it's receiving the mods after the disconnect is called. There is definitely a race condition but why I don't know. I wonder if it's a poor ordering of the configuration tasks. I would need a debug log from the server to be sure, since I have extra information logged there
Yeah you may be right. I forgot the "server" is just a client that is opened to lan, so of course it would be affected in the same way, and I see that is the case for the host too:
[17:46:23] [Netty Local Client IO #2/ERROR]: Server is missing required mod(s). Remove these from your client to join this server. [unicopia, unicopia-blockus]
[17:46:23] [Netty Local Client IO #2/INFO]: Connection would fail with message 'translation{key='fabwork.error.server_missing_mods', args=[unicopia, unicopia-blockus]}' but was allowed anyway due to configured rules.
[17:46:23] [Netty Server IO #5/INFO]: Sending mod list to Lilac_Firefly[local:E:f91bf3fa]
[17:46:23] [Netty Local Client IO #2/INFO]: Got mod list from server: [unicopia, unicopia-blockus] (2)
[17:46:23] [Netty Server IO #5/INFO]: Got mod list from Lilac_Firefly[local:E:f91bf3fa]: [unicopia, unicopia-blockus] (2)
[17:46:23] [Netty Server IO #5/INFO]: Connection succeeded with 2 syncronised mod(s) [unicopia, unicopia-blockus]
Connection isn't being closed by Fabwork in any case, and even though the order is swapped, on the host's side things look normal up until the point where coppercore joins. After that suddenly we get this error:
[17:47:43] [Netty Server IO #7/ERROR]: Error receiving packet 24
java.lang.IndexOutOfBoundsException: readerIndex: 24, writerIndex: 22 (expected: 0 <= readerIndex <= writerIndex <= capacity(256))
at io.netty.buffer.AbstractByteBuf.checkIndexBounds(AbstractByteBuf.java:112) ~[netty-buffer-4.1.97.Final.jar:4.1.97.Final]
at io.netty.buffer.AbstractByteBuf.readerIndex(AbstractByteBuf.java:121) ~[netty-buffer-4.1.97.Final.jar:4.1.97.Final]
at net.minecraft.class_2540.method_52988(class_2540.java:855) ~[minecraft-1.20.4.i0:0/:?]
at net.minecraft.class_2540.readerIndex(class_2540.java:85) ~[minecraft-1.20.4.i0:0/:?]
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1097) ~[netty-buffer-4.1.97.Final.jar:4.1.97.Final]
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1087) ~[netty-buffer-4.1.97.Final.jar:4.1.97.Final]
at net.minecraft.class_2540.method_52975(class_2540.java:1519) ~[minecraft-1.20.4.i0:0/:?]
at org.quiltmc.qsl.networking.impl.payload.PacketByteBufPayload.method_53028(PacketByteBufPayload.java:26) ~[quilt-networking-8.0.0-alpha.121.20.4.i0:0/:?]
at net.minecraft.class_2658.method_11052(class_2658.java:89) ~[minecraft-1.20.4.i0:0/:?]
at net.minecraft.class_2545.method_10838(class_2545.java:47) ~[minecraft-1.20.4.i0:0/:?]
at net.minecraft.class_2545.encode(class_2545.java:15) ~[minecraft-1.20.4.i0:0/:?]
at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:107) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:881) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:863) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:968) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:856) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:113) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:881) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:940) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:966) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:934) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:984) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1025) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:306) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at net.minecraft.class_2535.method_36942(class_2535.java:321) ~[minecraft-1.20.4.i0:0/:?]
at net.minecraft.class_2535.method_52917(class_2535.java:316) ~[minecraft-1.20.4.i0:0/:?]
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) ~[netty-common-4.1.97.Final.jar:4.1.97.Final]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) ~[netty-common-4.1.97.Final.jar:4.1.97.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) ~[netty-common-4.1.97.Final.jar:4.1.97.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.97.Final.jar:4.1.97.Final]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.97.Final.jar:4.1.97.Final]
at java.lang.Thread.run(Unknown Source) ~[?:?]
Thanks! That tells me a lot! From a quick scan it looks like the mod consent packet failed to parse, but I'll need to look close and not from my phone.
I don't think this is a fabworks issue since I know world edit also has a similar issue
With some help I was able to enable more debug logging, do these help any?
Client running as Server in Open LAN: https://mclo.gs/NpXrDPa
Running as Client: https://mclo.gs/1SDLK0t
Just doing more info gathering. I fired up a dedicated server, and only when a second player connects does this happen below. The first player to connect is able to play normally.
Client side error:
[18:57:04] [Netty Client IO #1/ERROR]: Encountered exception while handling in channel with name "unicopia:other_player_capabilities" java.lang.IndexOutOfBoundsException: null at io.netty.buffer.EmptyByteBuf.readLong(EmptyByteBuf.java:593) ~[netty-buffer-4.1.97.Final.jar:4.1.97.Final] at net.minecraft.network.PacketByteBuf.readLong(PacketByteBuf.java:1338) ~[minecraft-1.20.4.i0:0/:?] at net.minecraft.network.PacketByteBuf.readUuid(PacketByteBuf.java:542) ~[minecraft-1.20.4.i0:0/:?] at com.minelittlepony.unicopia.network.MsgPlayerCapabilities.<init>(MsgPlayerCapabilities.java:32) ~[unicopia-1.3.61.20.4.i0:0/:?] at com.minelittlepony.unicopia.network.MsgOtherPlayerCapabilities.<init>(MsgOtherPlayerCapabilities.java:15) ~[unicopia-1.3.61.20.4.i0:0/:?] at com.sollace.fabwork.impl.packets.ClientSimpleNetworkingImpl.lambda$register$1(ClientSimpleNetworkingImpl.java:21) ~[fabwork-1.3.01.20.2.i0:0/:?] at net.fabricmc.fabric.api.client.networking.v1.ClientPlayNetworking$PlayChannelHandler.receive(ClientPlayNetworking.java:381) ~[quilted-fabric-networking-api-v1-9.0.0-alpha.80.97.0-1.20.4.i0:0/:?] at org.quiltmc.qsl.networking.api.client.ClientPlayNetworking$ChannelReceiver.receive(ClientPlayNetworking.java:336) ~[quilt-networking-8.0.0-alpha.131.20.4.i0:0/:?] at org.quiltmc.qsl.networking.api.client.ClientPlayNetworking$ChannelReceiver.receive(ClientPlayNetworking.java:330) ~[quilt-networking-8.0.0-alpha.131.20.4.i0:0/:?] at org.quiltmc.qsl.networking.impl.client.ClientPlayNetworkAddon.receive(ClientPlayNetworkAddon.java:81) ~[quilt-networking-8.0.0-alpha.131.20.4.i0:0/:?] at org.quiltmc.qsl.networking.impl.client.ClientPlayNetworkAddon.receive(ClientPlayNetworkAddon.java:42) ~[quilt-networking-8.0.0-alpha.131.20.4.i0:0/:?] at org.quiltmc.qsl.networking.impl.AbstractChanneledNetworkAddon.handle(AbstractChanneledNetworkAddon.java:94) ~[quilt-networking-8.0.0-alpha.131.20.4.i0:0/:?] at net.minecraft.client.network.ClientCommonNetworkHandler.handler$cpd000$quilt_networking$handleCustomPayload(ClientCommonNetworkHandler.java:539) ~[minecraft-1.20.4.i0:0/:?] at net.minecraft.client.network.ClientCommonNetworkHandler.onCustomPayload(ClientCommonNetworkHandler.java) ~[minecraft-1.20.4.i0:0/:?] at net.minecraft.network.packet.s2c.common.CustomPayloadS2CPacket.apply(CustomPayloadS2CPacket.java:94) ~[minecraft-1.20.4.i0:0/:?] at net.minecraft.network.packet.s2c.common.CustomPayloadS2CPacket.apply(CustomPayloadS2CPacket.java:32) ~[minecraft-1.20.4.i0:0/:?] at net.minecraft.network.ClientConnection.handlePacket(ClientConnection.java:196) ~[minecraft-1.20.4.i0:0/:?] at net.minecraft.network.ClientConnection.channelRead0(ClientConnection.java:181) ~[minecraft-1.20.4.i0:0/:?] at net.minecraft.network.ClientConnection.channelRead0(ClientConnection.java:60) ~[minecraft-1.20.4.i0:0/:?] at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.flow.FlowControlHandler.dequeue(FlowControlHandler.java:202) ~[netty-handler-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.flow.FlowControlHandler.channelRead(FlowControlHandler.java:164) ~[netty-handler-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:333) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:454) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103) ~[netty-codec-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) ~[netty-handler-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.97.Final.jar:4.1.97.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.97.Final.jar:4.1.97.Final] at java.lang.Thread.run(Thread.java:840) ~[?:?]