[Bug] Random Socket Closure during mod download
OfficialLambdax opened this issue · 17 comments
Fill out general information
OS (windows, linux, ...): Windows (maybe Linux)
BeamMP-Launcher Version: 2.0.77
Describe the bug
The launcher disconnects from the server during the download of mods from the server. This happens while the mod is downloaded not in between them. A wireshark capture and the server/client logs implie that the disconnect happens intentionally from the Launcher.
[23/9/2022 00:01:57] [INFO] Launcher version is up to date
[23/9/2022 00:01:57] [INFO] Game Version : 0.26.1.0
[23/9/2022 00:01:57] [WARN] Game is newer than recommended, multiplayer may not work as intended!
[23/9/2022 00:01:57] [INFO] Downloading mod please wait...
[23/9/2022 00:01:58] [INFO] Download Complete!
[23/9/2022 00:01:58] [INFO] Game Launched!
[23/9/2022 00:02:13] [INFO] Game Connected!
[23/9/2022 00:02:13] [WARN] Game Reconnecting...
[23/9/2022 00:02:14] [INFO] Game Connected!
[23/9/2022 00:02:29] [INFO] Attempting to authenticate...
[23/9/2022 00:02:29] [INFO] Attempting to authenticate...
[23/9/2022 00:02:29] [INFO] Authentication successful!
[23/9/2022 00:02:30] [INFO] Authentication successful!
[23/9/2022 00:02:33] [INFO] Connecting to server
[23/9/2022 00:02:33] [INFO] Connected!
[23/9/2022 00:02:33] [INFO] Checking Resources...
[23/9/2022 00:02:33] [INFO] Syncing...
[23/9/2022 00:03:54] [INFO] 0 <<<<<<<<------------------
[23/9/2022 00:03:54] [WARN] Failed to close socket!
The Zero in the launcher log comes from:
https://github.com/BeamMP/BeamMP-Launcher/blob/master/src/Network/Resources.cpp#L132
which is the return of recv().
"If the connection has been gracefully closed, the return value is zero."
https://learn.microsoft.com/en-us/windows/win32/api/winsock/nf-winsock-recv
This means that the connection has been intentionally closed and the capture point towards the launcher causing it.
To Reproduce
Steps to reproduce the behavior:
I personally could not reproduce the bug, but these seem to be the steps to reproduce the bug. The bug does not happen each time. And seems to occure more often when the connecting player is far away from the server location (e.g. USA <-> GER)
- Setup a Server
- Put a bunch of Mods into the Client resource folder (it appears that the larger the mod, the more likely it is that the bug occurs e.g. a 700mb mod)
- Connect to the Server with the game until the bug appears during mod download (you might have to delete the mods from your launcher resources folder to trigger the download again)
= You will see "Socket Closed Code 1" in the Lua mod and the 0 in the launcher when the bug has been reproduced successfully.
Logs
The Discord user Oro#9824 was so friendly to help debugging the bug so far and also uploaded the logs and capture here
https://www.dropbox.com/s/r3h7uom20dc91p5/Crash.7z?dl=0
Additional context
A ton of players already reported this bug in the dc by now
according to https://learn.microsoft.com/en-us/windows/win32/api/winsock/nf-winsock-recv
example code given reflects the fact that if the winsock recv function returns 0 the connection is therefore terminated
else if ( iResult == 0 ) printf("Connection closed\n");
-1 is the return if the socket was closed unintentionally (connection lost for example), while the 0 clearly says that one of the two parties intented to close the socket
yes it is the only way to know, this check was added because of the fact that it would otherwise hang for an indefinite amount of time simply receiving 0, further strengthening the fact that 0 means closed.
if it would get a -1 we would simply see the cause by calling WSAGetLastError
but since we get a 0 it points towards a bug, because that return only can be get when the socket has been closed intentionally. And in this case likely by the launcher, as the capture tells us
https://i.imgur.com/KFcMbd7.png
according to your picture the packet has the RST flag.
"In TCP, packets with the "Reset" (RST or R) flag are sent to abort a connection. Probably the most common reason you are seeing this is that an SYN packet is sent to a closed port. But RST packets may be sent in other cases to indicate that a connection should be closed."
Closing a download socket gracefully should not stop anything, we should continue normally. No?
Closing a download socket gracefully should not stop anything, we should continue normally. No?
we failed to get any data from the very socket the connection continues on, there is nothing left to salvage from that ;/
that is why we exploring new ideas on mod download, so that if the connection gets randomly cut we can try and resume for example :D
Well currently it affects dozens of players that play on modded servers
thank you for the bug report, as I think it will be very helpful for us to mention it in the next dev meetings, I will see to it personally that the issue is fixed as soon as we decide as a team on a new network design.
Hi, I am one of the people reported this bug and I also provided the wireshark log.
Additionally here is the server log from today. You can see that a player is trying to connecting, but the mod download gets interrupted every time.
Unfortunately this bug will block many players to experience modded server.
I am happy to assist troubleshooting and finding the root of this bug. Please let me know if you need any additional information or any other help. Discord: Oro#9824
Ps. in the last months this was not a problem. I am running this amount of mods for a few months, without any problems. Even if user got a slow internet connection and the download took sometimes 30min +, there were no interruption. This bug just occurred in the last 2-3 weeks I would say, not sure about a exact time frame.
Serverlog
[24/09/22 14:51:33] [INFO] BeamMP Server v3.0.2
[24/09/22 14:51:33.381] [DEBUG] Debug: true
[24/09/22 14:51:33.381] [DEBUG] Private: false
[24/09/22 14:51:33.381] [DEBUG] Port: 30814
[24/09/22 14:51:33.381] [DEBUG] MaxCars: 3
[24/09/22 14:51:33.381] [DEBUG] MaxPlayers: 10
[24/09/22 14:51:33.381] [DEBUG] Map: "/levels/ogc_map/info.json"
[24/09/22 14:51:33.382] [DEBUG] Name: "[^cOfficial OGC Server | Ver. 0.26^r] ^bUltimate Beam Map!^r ^4^oExclusive^r ^6//^r 40+ Cars (^6BMW, Mercedes etc^r)"
[24/09/22 14:51:33.382] [DEBUG] Description: "^6Enjoy your stay! Questions/Support/Feedback? Join our Discord:^r ^bhttps://discord.gg/5u9yTMBPUp^r | ^n^4Exclusive Map for that Server^r | ^2Very Frequent Updates for Cars and Map^r ^6//^r ^n^oDisclaimer: Credits for every Car mod in zip files!^r"
[24/09/22 14:51:33.382] [DEBUG] ResourceFolder: "Resources"
[24/09/22 14:51:33.382] [DEBUG] SSLKeyPath: "./.ssl/HttpServer/key.pem"
[24/09/22 14:51:33.383] [DEBUG] SSLCertPath: "./.ssl/HttpServer/cert.pem"
[24/09/22 14:51:33.383] [DEBUG] HTTPServerPort: "8080"
[24/09/22 14:51:33.383] [DEBUG] HTTPServerIP: "127.0.0.1"
[24/09/22 14:51:33.383] [DEBUG] Key Length: 36
[24/09/22 14:51:33.386] PluginMonitor [INFO] PluginMonitor started
[24/09/22 14:51:33.386] LuaEngine [EVENT] onInit
[24/09/22 14:51:33.386] Main [INFO] Sentry started! Reporting errors automatically. This sends data to the developers in case of errors and crashes. You can learn more, turn this message off or opt-out of this in the ServerConfig.toml.
[24/09/22 14:51:33.388] Main [INFO] Loaded 13 Mods
[24/09/22 14:51:33.389] PPSMonitor [DEBUG] PPSMonitor starting
[24/09/22 14:51:33.390] TCPServer [INFO] Vehicle event network online
[24/09/22 14:51:33.390] UDPServer [INFO] Vehicle data network online on port 30814 with a Max of 10 Clients
[24/09/22 14:51:33.473] Main [INFO] Server up-to-date!
[24/09/22 14:51:38.425] Heartbeat [DEBUG] heartbeat (after 5s)
[24/09/22 14:51:38.745] Heartbeat [INFO] Resumed authenticated session!
[24/09/22 14:51:38.839] Main(Waiting) [INFO] ALL SYSTEMS STARTED SUCCESSFULLY, EVERYTHING IS OKAY
[24/09/22 14:52:08.490] Heartbeat [DEBUG] heartbeat (after 30s)
[24/09/22 16:29:18.836] Heartbeat [DEBUG] heartbeat (after 30s)
[24/09/22 16:29:30.651] Identify [INFO] Identifying new ClientConnection...
[24/09/22 16:29:30.774] Identify [DEBUG] Name -> MysTi, Guest -> 0, Roles -> USER
[24/09/22 16:29:30.774] Identify [EVENT] onPlayerAuth
[24/09/22 16:29:30.774] Identify [INFO] Identification success
[24/09/22 16:29:30.774] Identify [DEBUG] inserting client (0)
[24/09/22 16:29:30.776] Identify [INFO] Client connected
[24/09/22 16:29:30.776] Identify [INFO] Assigned ID 0 to MysTi
[24/09/22 16:29:30.777] Identify [EVENT] onPlayerConnecting
[24/09/22 16:29:30.793] Identify [DEBUG] Sending Mod Info
[24/09/22 16:29:30.851] Heartbeat [DEBUG] heartbeat (after 12s)
[24/09/22 16:29:30.864] Identify [INFO] MysTi requesting : /OGC_Audi.zip
[24/09/22 16:29:30.874] SplitLoad_0 [DEBUG] Split load Socket 1440
[24/09/22 16:29:30.877] SplitLoad_1 [DEBUG] Split load Socket 816
[24/09/22 16:29:34.487] (0) "MysTi" [DEBUG] client status < 0, breaking client loop
[24/09/22 16:29:34.489] Looper [DEBUG] client status < 0, breaking client loop
[24/09/22 16:29:34.489] (0) "MysTi" [INFO] MysTi Connection Terminated
[24/09/22 16:29:34.489] (0) "MysTi" [EVENT] onPlayerDisconnect
[24/09/22 16:29:34.490] (0) "MysTi" [DEBUG] removing client MysTi (1)
[24/09/22 16:29:35.945] Heartbeat [DEBUG] heartbeat (after 5s)
[24/09/22 16:30:06.023] Heartbeat [DEBUG] heartbeat (after 30s)
[24/09/22 16:30:26.553] Identify [INFO] Identifying new ClientConnection...
[24/09/22 16:30:26.664] Identify [DEBUG] Name -> MysTi, Guest -> 0, Roles -> USER
[24/09/22 16:30:26.664] Identify [EVENT] onPlayerAuth
[24/09/22 16:30:26.664] Identify [INFO] Identification success
[24/09/22 16:30:26.664] Identify [DEBUG] inserting client (0)
[24/09/22 16:30:26.664] Identify [INFO] Client connected
[24/09/22 16:30:26.667] Identify [INFO] Assigned ID 0 to MysTi
[24/09/22 16:30:26.667] Identify [EVENT] onPlayerConnecting
[24/09/22 16:30:26.686] Identify [DEBUG] Sending Mod Info
[24/09/22 16:30:26.718] Identify [INFO] MysTi requesting : /OGC_Audi.zip
[24/09/22 16:30:26.773] Heartbeat [DEBUG] heartbeat (after 20s)
[24/09/22 16:30:26.825] SplitLoad_0 [DEBUG] Split load Socket 1192
[24/09/22 16:30:26.828] SplitLoad_1 [DEBUG] Split load Socket 1188
[24/09/22 16:30:56.852] Heartbeat [DEBUG] heartbeat (after 30s)
[24/09/22 16:32:57.071] Heartbeat [DEBUG] heartbeat (after 30s)
[24/09/22 16:33:15.586] Identify [INFO] MysTi requesting : /OGC_BMW.zip
[24/09/22 16:33:15.627] SplitLoad_1 [DEBUG] Split load Socket 1188
[24/09/22 16:33:15.627] SplitLoad_0 [DEBUG] Split load Socket 1192
[24/09/22 16:33:27.166] Heartbeat [DEBUG] heartbeat (after 30s)
[24/09/22 16:33:46.072] SplitLoad_0 [INFO] Socket Closed! 1192
[24/09/22 16:33:46.103] SplitLoad_1 [INFO] Socket Closed! 1188
[24/09/22 16:33:46.109] (0) "MysTi" [DEBUG] client status < 0, breaking client loop
[24/09/22 16:33:46.110] Looper [DEBUG] client status < 0, breaking client loop
[24/09/22 16:33:46.110] (0) "MysTi" [INFO] MysTi Connection Terminated
[24/09/22 16:33:46.111] (0) "MysTi" [EVENT] onPlayerDisconnect
[24/09/22 16:33:46.111] (0) "MysTi" [DEBUG] removing client MysTi (1)
[24/09/22 16:33:46.181] Heartbeat [DEBUG] heartbeat (after 19s)
[24/09/22 16:39:16.762] Heartbeat [DEBUG] heartbeat (after 30s)
[24/09/22 16:39:28.977] Identify [INFO] Identifying new ClientConnection...
[24/09/22 16:39:29.091] Identify [DEBUG] Name -> MysTi, Guest -> 0, Roles -> USER
[24/09/22 16:39:29.091] Identify [EVENT] onPlayerAuth
[24/09/22 16:39:29.091] Identify [INFO] Identification success
[24/09/22 16:39:29.091] Identify [DEBUG] inserting client (0)
[24/09/22 16:39:29.093] Identify [INFO] Client connected
[24/09/22 16:39:29.094] Identify [INFO] Assigned ID 0 to MysTi
[24/09/22 16:39:29.094] Identify [EVENT] onPlayerConnecting
[24/09/22 16:39:29.110] Identify [DEBUG] Sending Mod Info
[24/09/22 16:39:29.200] Heartbeat [DEBUG] heartbeat (after 12s)
[24/09/22 16:39:29.538] Identify [INFO] MysTi requesting : /OGC_BMW.zip
[24/09/22 16:39:29.562] SplitLoad_1 [DEBUG] Split load Socket 1176
[24/09/22 16:39:29.563] SplitLoad_0 [DEBUG] Split load Socket 1192
[24/09/22 16:39:40.190] SplitLoad_0 [INFO] Socket Closed! 1192
[24/09/22 16:39:46.345] SplitLoad_1 [INFO] Socket Closed! 1176
[24/09/22 16:39:46.352] (0) "MysTi" [DEBUG] client status < 0, breaking client loop
[24/09/22 16:39:46.352] Looper [DEBUG] client status < 0, breaking client loop
[24/09/22 16:39:46.352] (0) "MysTi" [INFO] MysTi Connection Terminated
[24/09/22 16:39:46.352] (0) "MysTi" [EVENT] onPlayerDisconnect
[24/09/22 16:39:46.353] (0) "MysTi" [DEBUG] removing client MysTi (1)
[24/09/22 16:39:46.356] Heartbeat [DEBUG] heartbeat (after 17s)
[24/09/22 16:40:16.403] Heartbeat [DEBUG] heartbeat (after 30s)
@OfficialLambdax already included a server log in his report and did mention you, that said this paste of the log cannot be minimized, so can you please edit the message, thank you.
Closing a download socket gracefully should not stop anything, we should continue normally. No?
we failed to get any data from the very socket the connection continues on, there is nothing left to salvage from that ;/
The download sockets are separate from the main TCP socket, the download socket closing is required at one point for the download to finish.
Closing a download socket gracefully should not stop anything, we should continue normally. No?
we failed to get any data from the very socket the connection continues on, there is nothing left to salvage from that ;/
The download sockets are separate from the main TCP socket, the download socket closing is required at one point for the download to finish.
we use the main TCP socket and another one
Have not read about this bug reappearing since the 0.27 mp update. might be resolved
Hi, I can report, that on my server all mod downloads work flawless again. Not sure if the beammp update, or version 0.27 fixed it. But I don't have any issues anymore.
Thanks for checking it.