search

Mydayyy / Valheim-ServerSideMap

This plugin completely moves the explored map and created pins to the server. As clients explore, they will send their explored areas to the server who will then distribute it to all connected clients. When a client joins, the server will synchronize the currently explored areas to the client. Pins are shared as well but default to false and need to be enabled. When pin sharing is used, all newly created pins are send to the server who saves them along with the explored area.
38 stars 1 forks source link

Server completely un-joinable after restart, corrupted .explored files? #18

Closed brahaney closed 3 years ago

brahaney commented 3 years ago

First off-- love the mod concept. Until a restart it works great! My friends and I were loving the sharing. If theres any way I can help to further debug this or anything please let me know. I'm a Software Engineer in Test so, testing/debugging is my jam. Is there a way to activate like a debug mode for BepInEx or just this mod, to get some logging from the events I describe below? Currently nothing at all happens in the logs.

The issue

This issue is consistently replicable in my environment. I have not yet tried isolating just this mod to replicate but if I have time to do so I will post my findings.

My server is scheduled to do check for updates nightly, which currently results in a restart. Each morning this results in being completely unable to reconnect to the server. There are no errors in the server log or client log-- when connecting, instead of prompting for my password, I get the following two screens:

image image

The connection issue applies to all users, not only users with the mod installed. One of our players is still running completely vanilla client and cannot connect either once this issue begins.

I've deduced this to be an issue with SSM. It's the only mod I had added since the crashes started, and I can resolve the issue without removing the mod from the server or by simply deleting or moving Wootheim2.mod.serversidemap.explored and restarting.

This issue has replicated each time my server has restarted to check for updates, and can be replicated in my environment below with a simple docker-compose restart command.

I have also attached two of the "corrupted" (I guess?) .explored files, not sure if they're helpful. wootheim-explored-files.zip

Environment

latest version of Valheim dedicated server, linux (containerized in docker), with only a handful of mods:

I also attached my zipped config directory in case anything in there helps. wootheim-config.zip

I run the entire thing in docker, using mbround18/valheim docker image and the following docker-compose.yml

version: "3"
services:
  valheim:
    image: mbround18/valheim:latest
    ports:
      - 2456:2456/udp
      - 2457:2467/udp
      - 2458:2458/udp
    environment:
      - PORT=2456
      - NAME="Wootheim"
      - WORLD="Wootheim2"
      - PASSWORD="coolkids!"
      - TZ=America/Chicago
      - PUBLIC=1
      - AUTO_UPDATE=1
      - AUTO_UPDATE_SCHEDULE="0 1 * * *"
      - AUTO_BACKUP=1
      - AUTO_BACKUP_SCHEDULE="*/15 * * * *"
      - AUTO_BACKUP_REMOVE_OLD=1
      - AUTO_BACKUP_DAYS_TO_LIVE=3
      - AUTO_BACKUP_ON_UPDATE=1
      - AUTO_BACKUP_ON_SHUTDOWN=1
      - UPDATE_ON_STARTUP=0
    volumes:
      - /home/valheim/saves:/home/steam/.config/unity3d/IronGate/Valheim
      - /home/valheim/server:/home/steam/valheim
      - /home/valheim/backups:/home/steam/backups
Mydayyy commented 3 years ago

Oooh thats interesting. So far I had only one other user run into the same problem and I thought it was an issue with the used docker image (which was pterodactyl), but I couldnt for the life of me reproduce it, unfortunately he turned inactive.

I'll take a look at everything and try to reproduce it, I hope I can catch that slippery bug this time. The bug report is certainly extremely useful, thank you :)

Cheers Mydayyy

I'll be pasting the report about the same bug from NexusMods here so I have it in one place

This mod is crashing on linux server (debian) after the first map file is generated. clean install. clean mod. loads server fine. runs fine. reboot server. server crashes. only mod installed is this one. using newest update. i made sure the ServerSideMap data file had 755 permissions (default 644). still crashed.

02/26/2021 18:04:05: Load world Dedicated
[Info: Unity Log] 02/26/2021 18:04:05: Loading 245980 zdos , my id 1809509064 data version:26
02/26/2021 18:04:05: Loading 245980 zdos , my id 1809509064 data version:26
[Info: Unity Log] 02/26/2021 18:04:07: Loaded 100000 dead zdos
02/26/2021 18:04:07: Loaded 100000 dead zdos
[Info: Unity Log] 02/26/2021 18:04:07: Removed 0 OLD generated ZDOS
02/26/2021 18:04:07: Removed 0 OLD generated ZDOS
[Info: Unity Log] 02/26/2021 18:04:07: Loaded 7132 locations
02/26/2021 18:04:07: Loaded 7132 locations
[Info:ServerSideMap] loaded from existing explore file
[Info:ServerSideMap] loaded from existing explore file
[Info: SSM] ZNet awake
[Info: SSM] ZNet awake
[Info: Unity Log] 02/26/2021 18:04:08: Audioman already exist, destroying self
02/26/2021 18:04:08: Audioman already exist, destroying self
[Info: SSM] Minimap awake
[Info: SSM] Minimap awake
Unloading 490 unused Assets to reduce memory usage. Loaded Objects now: 86310.
Total: 339.325979 ms (FindLiveObjects: 10.222977 ms CreateObjectMapping: 19.696776 ms MarkObjects: 300.290219 ms  DeleteObjects: 9.108143 ms)
./launch_server.sh: line 29: 75 Killed./valheim_server.x86_64 -nographics -batchmode -name $1 -port $2 -world $3 -password $4
container@pterodactyl~ Server marked as offline...

Here is the code after deleting the Dedicated.serversidemap.explored file (server runs great until its rebooted)

[Info   : Unity Log] 02/26/2021 18:06:32: Load world Dedicated
02/26/2021 18:06:32: Load world Dedicated
[Info   : Unity Log] 02/26/2021 18:06:32: Loading 245980 zdos , my id -106203805 data version:26
02/26/2021 18:06:32: Loading 245980 zdos , my id -106203805 data version:26
[Info   : Unity Log] 02/26/2021 18:06:34: Loaded 100000 dead zdos
02/26/2021 18:06:34: Loaded 100000 dead zdos
[Info   : Unity Log] 02/26/2021 18:06:34: Removed 0 OLD generated ZDOS
02/26/2021 18:06:34: Removed 0 OLD generated ZDOS
[Info   : Unity Log] 02/26/2021 18:06:34: Loaded 7132 locations
02/26/2021 18:06:34: Loaded 7132 locations
[Info   :ServerSideMap] new explore file generated
[Info   :ServerSideMap] new explore file generated
[Info   : Unity Log] 02/26/2021 18:06:35: clone 655
02/26/2021 18:06:35: clone 655
02/26/2021 18:06:36: Saved 245980 zdos
02/26/2021 18:06:36: World saved ( 1471.519ms )
[Info   :       SSM] ZNet awake
[Info   :       SSM] ZNet awake
[Info   : Unity Log] 02/26/2021 18:06:36: Audioman already exist, destroying self
02/26/2021 18:06:36: Audioman already exist, destroying self
[Info   :       SSM] Minimap awake
[Info   :       SSM] Minimap awake
Unloading 490 unused Assets to reduce memory usage. Loaded Objects now: 86310.
Total: 328.353114 ms (FindLiveObjects: 6.604399 ms CreateObjectMapping: 13.263506 ms MarkObjects: 303.803330 ms  DeleteObjects: 4.674617 ms)
[Info   : Unity Log] 02/26/2021 18:06:42: Zonesystem Start 186
02/26/2021 18:06:42: Zonesystem Start 186
[Info   : Unity Log] 02/26/2021 18:06:43: DungeonDB Start 186
container@pterodactyl~ Server marked as running...
02/26/2021 18:06:43: DungeonDB Start 186
weebs commented 3 years ago

Looks like this is why I had to disable the mod on my server. I assumed it was due to the newest update being incompatible with the patch, but after removing the .explored file, I'm able to use the mod again.

Something I noticed about the issue is the valheim server process RAM usage would quickly explode to 100% and essentially stall out my 4GB VPS instance. I wonder if my machine had more RAM it would be able to get the server up and running?

I'm running an ubuntu based VPS with the dedicated server setup through LGSM (https://linuxgsm.com/lgsm/vhserver/)

Mydayyy commented 3 years ago

He, that could certainly be it, and I can reproduce that. I wonder where I screwed that up, wow. I'll take a look in 2 hours, but that should definitely not be happening but thats atleast something thats somehow easy to find/track

brahaney commented 3 years ago

Ok so it seems like its related to how much data is in the shared map-- Me and my friends all did a bunch of exploring late last night, as well as synced all of our maps with the server for the first time. After the reboot that night, my DigitalOcean droplet (2CPU/4GB RAM) was totally unresponsive, to the point where I couldn't even connect an SSH session. But since then I reproduced the issue a few times without any performance issues by starting the server, connecting to sync my map, and then restarting the server.

Mydayyy commented 3 years ago

Greetings,

I put out a rc-1.2.1 which should fix that issue: https://github.com/Mydayyy/Valheim-ServerSideMap/releases/download/rc1-1.2.1/ServerSideMap.zip

What went wrong? I was using var data = reader.ReadBytes(int.MaxValue); to read all bytes in the exploration file at once, and as stated by the documentation: Passing int.maxValue might return less bytes if an end of stream is reached. What it didn't tell me is that, .net will still allocate a freaking 4GB array of data, even if the file size is less than an int.MaxValue.

https://docs.microsoft.com/en-us/dotnet/api/system.io.binaryreader.readbytes?redirectedfrom=MSDN&view=net-5.0#System_IO_BinaryReader_ReadBytes_System_Int32_

A byte array containing data read from the underlying stream. This might be less than the number of bytes requested if the end of the stream is reached.

Found that out via https://stackoverflow.com/a/8613300

If you can spare a minute I'd be happy to know whether the new RC works for you. I didn't notice any memory overhead anymore.

Cheers Mydayyy

Edit: Also @brahaney: In case the new RC works for you, you should be able to plop the old .explored files right back in. I checked them and they are not damaged.

brahaney commented 3 years ago

It's fixed! Amazing. Thanks for the speedy response, we were really excited to use this mod! Feel free to ping me if you've got new versions or features to test.

Mydayyy commented 3 years ago

Glad to hear!

I released 1.2.1 as a new version on NexusMods and Thunderstore. If you're already running the rc1-1.2.1 there's no need to update, there weren't any changes except a formal release. Incredible sorry for this bug, thank you for the great report!

Cheers Mydayyy