Plasmo Voice on universespigot 1.21.1 randomly doesn't connect to the player when connecting to a specific server

[tetram2674562]

Description of the bug

Everything was working fine for a few months and then lately we've got a problem with plasmo voice randomly not connecting with players on our server (only one out of the 9). We tried downgrading to 2.1.2, then updating to 2.1.4 then to 2.1.5 then to 2.1.6 (latest snapshot) but It won't stop happening randomly. This bug is appearing only on the "spawn" server (we've got a total of 9 servers with their files synchronised between each other).

Temporary fix

We've got a fix, just ask a player to try to disconnect/reconnect from the server until it works. (this is horrible)

Technical description of the bug

We've activated debug mode of plasmo voice and found out the server is randomly not sending the connection packet, stopping at the player info request.

Specification of the server

Velocity with the latest version of plasmo voice (2.1.6-SNAPSHOT)
Universe Spigot 1.21.1 with latest version of plasmo voice (2.1.6-SNAPHOT)

We would really like to fix this bug, this has become horrible for us, so if you need any extra information, just ask!
Excuse myself for my poor english language

[apehum]

Does this happens to specific players or completely random?

[tetram2674562]

It's totally random and can append to anyone.

[apehum]

This "spawn" server is the first server players are connecting to on the proxy? If so, when you rejoin this "spawn" server within the proxy, does this fix the issue?

[tetram2674562]

So first they get to a login server named "auth2" then goes to the "spawn" server.
And no, It doesn't fix the issue... When the player comes from another server than the "spawn" server (let's say from the "end" server) It can also append that their voice chat is unable to connect to the server.

[apehum]

Error message in the menu when player joins from "auth2" to "spawn" is "Plasmo Voice is not installed on this server"?

[tetram2674562]

Well yes I got a message from "auth2" to "spawn" that have "Plasmo Voice is not installed on this server".
But from the "end" server to the "spawn" server I get the "Connecting to UDP server..." message.

[apehum]

Yeah, thanks.
It sounds like request packet not even leaves the backend server, but I have no idea how is that possible with 2.1.6 and 1.21.1.

I've added verbose packet logging on proxy-side with debug enabled in the latest snapshot. Install it on the Velocity and see if PlayerInfoRequestPacket reaches the Velocity when it sent from the backend server.

[tetram2674562]

Thanks you for adding this to your plugin, I applied this snapshot on the proxy. I'll send you a few parts of the plasmovoice log on the proxy soon.

[tetram2674562]

So here is I got the problem again.
Here a part of the proxy log :

[20:09:13] [Netty epoll Worker #13/INFO] [com.velocitypowered.proxy.connection.MinecraftConnection]: [server connection] gaspardAlizand -> Spawn has connected
[20:09:13] [Netty epoll Worker #13/INFO] [com.velocitypowered.proxy.connection.MinecraftConnection]: [server connection] gaspardAlizand -> Donjon has disconnected
[20:09:13] [VentureChat - Task Executor #1575/INFO] [PlasmoVoice]: su.plo.slib.velocity.connection.VelocityProxyServerConnection@28489a65 -> su.plo.slib.velocity.player.VelocityProxyPlayer@2ef4ef93: PlayerDisconnectPacket(playerId=b73bc776-dbab-3735-8e2d-d6c8636ad249)

And here is some parts of the spawn server log :

[20:09:13] [User Authenticator #108/INFO]: UUID of player gaspardAlizand is b73bc776-dbab-3735-8e2d-d6c8636ad249
[20:09:14] [Server thread/INFO]: gaspardAlizand[/myipsorry] logged in with entity id 2179246 at ([spawn]-1143.5887837200828, 25.0, 90.38435988866843)
[20:09:14] [Server thread/INFO]: [PlasmoVoice] Sent player info request packet to gaspardAlizand

I got the exact time when the bug appened and gave to you the part of the log concerning plasmo voice.
Nothing else was seen concerning my player or with my uuid at this time.
(Sorry for not providing the full log file, I just can't do that because I'm under contract with the server I'm working with)

[apehum]

Just as I though packet is not even sent from the backend server.

I've added more debug logs for the server-side (paper plugin) when request packet is sent in the latest snapshot.
You should have a channel list when request packet is sent:

[19:03:55 INFO]: [PlasmoVoice] Sent player info request packet to Apehum (channels: [fabric:attachment_sync_v1, fabric-screen-handler-api-v1:open_screen, plasmo:voice/v2/installed, plasmo:voice/v2, BungeeCord, plasmo:voice/v2/service])
[19:03:56 INFO]: [PlasmoVoice] Apehum registered channels: [fabric:attachment_sync_v1, frogdisplays:sync, frogdisplays:display_info, fabric-screen-handler-api-v1:open_screen, plasmo:voice/v2/installed, plasmo:voice/v2, BungeeCord, plasmo:voice/v2/service]. Response received: true. Join packet sent: true. Channel register packet sent: true

Send these logs when problem occurs again.

[tetram2674562]

I got the problem again, here are the logs of the exact moments it append :
This is the proxy logs (I took everything concerning my player)

10:54:05 INFO]: [server connection] gaspardAlizand -> Spawn has connected
[10:54:05 INFO]: [server connection] gaspardAlizand -> Mojave has disconnected
[10:54:05 INFO] [PlasmoVoice]: su.plo.slib.velocity.connection.VelocityProxyServerConnection@15e80a39 -> su.plo.slib.velocity.player.VelocityProxyPlayer@6b77d3f0: PlayerDisconnectPacket(playerId=b73bc776-dbab-3735-8e2d-d6c8636ad249)
[10:54:05 INFO] [PlasmoVoice]: su.plo.slib.velocity.connection.VelocityProxyServerConnection@1157fd24 -> su.plo.slib.velocity.player.VelocityProxyPlayer@6d76ba05: PlayerDisconnectPacket(playerId=b73bc776-dbab-3735-8e2d-d6c8636ad249)

And this is the universe spigot log (at the moment I was connecting) :

[10:54:06 INFO]: gaspardAlizand[/my ip again sorry] logged in with entity id 5503875 at ([spawn]-1262.4293620095714, 16.0, -65.80009768575957)
[10:54:06 INFO]: [PlasmoVoice] Sent player info request packet to gaspardAlizand (channels: [bungee:tp, axiom:editor_warning, axiom:marker_data, axiom:annotation_update, plasmo:voice/v2, whereisit:s2c_founditem, axiom:custom_blocks, axiom:response_chunk_data, fabric:attachment_sync_v1, architectury:spawn_entity_packet, axiom:response_entity_data, axiom:set_world_property, axiom:add_server_heightmap, fabric-screen-handler-api-v1:open_screen, axiom:register_world_properties, roughlyenoughitems:request_tags_s2c, axiom:blueprint_manifest, axiom:enable, axiom:ignore_display_entities, roughlyenoughitems:og_not_enough, tab:bridge-6, BungeeCord, roughlyenoughitems:ci_msg, axiom:register_custom_items, hope:hopecmdsend, axiom:marker_nbt_response, xconomy:aca, axiom:response_blueprint, xconomy:acb, marriagemaster:main, advancedban:main, axiom:redo_handshake, plasmo:voice/v2/installed, axiom:restrictions, plasmo:voice/v2/service, axiom:ack_world_properties, axiom:allowed_gamemodes])
[10:54:07 INFO]: [PlasmoVoice] gaspardAlizand registered channels: [bungee:tp, axiom:editor_warning, axiom:marker_data, axiom:annotation_update, plasmo:voice/v2, whereisit:s2c_founditem, axiom:custom_blocks, axiom:response_chunk_data, fabric:attachment_sync_v1, architectury:spawn_entity_packet, axiom:response_entity_data, axiom:set_world_property, axiom:add_server_heightmap, fabric-screen-handler-api-v1:open_screen, axiom:register_world_properties, roughlyenoughitems:request_tags_s2c, axiom:blueprint_manifest, axiom:enable, axiom:ignore_display_entities, roughlyenoughitems:og_not_enough, tab:bridge-6, roughlyenoughitems:ci_msg, axiom:register_custom_items, BungeeCord, hope:hopecmdsend, servux:litematics, axiom:marker_nbt_response, xconomy:aca, axiom:response_blueprint, xconomy:acb, marriagemaster:main, advancedban:main, axiom:redo_handshake, plasmo:voice/v2/installed, axiom:restrictions, plasmo:voice/v2/service, axiom:ack_world_properties, axiom:allowed_gamemodes]. Response received: false. Join packet sent: true. Channel register packet sent: false
[10:54:07 INFO]: [PlasmoVoice] Sent player info request packet to gaspardAlizand (channels: [bungee:tp, axiom:editor_warning, axiom:marker_data, axiom:annotation_update, plasmo:voice/v2, whereisit:s2c_founditem, axiom:custom_blocks, axiom:response_chunk_data, fabric:attachment_sync_v1, architectury:spawn_entity_packet, axiom:response_entity_data, axiom:set_world_property, axiom:add_server_heightmap, fabric-screen-handler-api-v1:open_screen, axiom:register_world_properties, roughlyenoughitems:request_tags_s2c, axiom:blueprint_manifest, axiom:enable, axiom:ignore_display_entities, roughlyenoughitems:og_not_enough, tab:bridge-6, BungeeCord, roughlyenoughitems:ci_msg, axiom:register_custom_items, hope:hopecmdsend, axiom:marker_nbt_response, xconomy:aca, axiom:response_blueprint, xconomy:acb, marriagemaster:main, advancedban:main, axiom:redo_handshake, plasmo:voice/v2/installed, axiom:restrictions, plasmo:voice/v2/service, axiom:ack_world_properties, axiom:allowed_gamemodes])

[apehum]

Thanks.

Well, I thought that channels are not registered properly and packet is not sent because of that, but it's clearly not the case. It would be really hard to investigate further without being able to reproduce this issue locally, so I'm not sure if it'll be fixed.

I made a workaround addon that should mitigate the issue (but not the cause): https://github.com/Apehum/pv-addon-request-resend. It sends request info packet multiple times until player is connected within config-specified timeout.

[tetram2674562]

Thanks you, I applied it on the server, I hope It'll fix the problem, thanks you again for taking time fixing this issue !