Duplicate servers

[Thin-Troll]

Describe the issue

Every day I reboot 7 servers at the same time, each of them has Plan installed, the plugins do not start when they are first turned on and there are no errors, they are simply displayed as Offline in the web part, if you restart them manually (/ plan reload), then the servers will be updated in the web part and will show statistics. Over time, the above process gives the effect of duplicate servers.

Exceptions & other logs

https://disk.yandex.ru/d/RctUPm9wAix-aA - ServerInfoFile.yml https://cdn.discordapp.com/attachments/466241867797889054/935615711496261632/unknown.png - information from mysql about all duplicates

Plugin versions

Plan 1516 paper 1.12.2 (build 1620)

Additional information

No response

[AuroraLS3]

TODO: Investigate the server information storage of game servers for any inconsistencies

[AuroraLS3]

Noted symptoms:

• Duplicate servers appear in the database
• Game server records data as a new server after restart (Thus previous server is appearing as offline)

• Plan reload recovers the state in a way that the new UUID is discarded and old UUID used again. (I don't understand how this happens)

  • This suggests that on the 2nd time loading from the file succeeds and the new UUID has not been stored in the file yet.

  • The information is written to the file after database query returns information.

    
    private Server registerNew(ServerUUID serverUUID) {
    Server server = createServerObject(serverUUID);
    fromDatabase.save(server);
    
    Server stored = fromDatabase.load(serverUUID)
            .orElseThrow(() -> new EnableException("Failed to register server (not found after saving to database)"));
    fromFile.save(stored);
    return stored;
    }

  private void updateStorage() { ... fromDatabase.save(server); server = fromDatabase.load(server.getUuid()).orElse(server); fromFile.save(server); }

  
  - But the server can't start with a new UUID without first writing it to the file, unless 

• The server info files match the information in the database (The ones with info in the files are set as installed)

Investigation

• Game servers try to load information from ServerInfoFile.yml and if that fails they register as a new server

      Optional<Server> loaded = fromFile.load(null);
      server = loaded.orElseGet(this::registerNew);

  • This suggests that the loading from the file fails on occasion during restarts.
  • Note that it is not possible to load the information from database if the file has no UUID, that's why new server is registered as it is assumed the server has no existing UUID

• the file loader returns empty if the value read from the config file is null

          if (!prepared) prepare();
  
          String serverUUIDString = getString("Server.UUID");
          if (serverUUIDString == null) return Optional.empty();

  • Preparation loads a yml file with empty values and copies missing fields. This is one place where the bug could be lurking

[Thin-Troll]

Ladder reboot solved the problem. After I transferred more problems were not observed

[AuroraLS3]

I could not figure why it happens, but I fixed some stuff and logging that could affect it. There is some multi-threading going on that could be do the odd things like reloading bringing back the old information.

Since this issue only pops up when database is busy during enable it's likely that some of the code covered for the underlying bug, executing fast enough to get the server information up to date. Anyway, if servers are registered now there is a log message to catch it so people may report more if it is a common bug.

[Thin-Troll]

oh damn literally 6 hours ago I deleted duplicate servers .. and I wanted to write, but here you are. any information required?

[AuroraLS3]

Another person had same issue so I reopened this.

Any logs with Registering a new server in database with UUID are appreciated as that logging was added during previous attempt of figuring this out

[Thin-Troll]

found nothing either in the BungeeCord logs or in the local servers that were created by the duplicate. Search in Plan > Logs and in the main server logs

Requested: Registering a new server in database with UUID

[AuroraLS3]

That is very odd.

[Thin-Troll]

Updated to 1661, servers are duplicated again, but this time there is a message Registering a new server in database with UUID

[AuroraLS3]

Okay at it is clear from the log order that the database had not yet completely opened before it decided to register a new server.

I'll take a look when I have the time.

[AuroraLS3]

Just to make sure (I can't remember if I have asked this) - did you delete /plugins/Plan/ServerInfoFile.yml when updating the plugin?

[Thin-Troll]

I updated the plugin and the servers were not duplicated. The file was not deleted.

[Thin-Troll]

Servers are duplicated again.

[AuroraLS3]

Somebody got this again on discord and their ServerInfoFile.yml cleared for some reason 🤔

[AuroraLS3]

Ok! Now I might have figured out what is happening: Two threads try to write the server details to the file at the same time, but by accident they write in the following sequence:

• Thread 1 reads defaults and puts them in memory
• Thread 1 reads written file contents in memory
• Thread 2 reads the defaults and overrides things in memory (because there isn't a proper concurrency access lock)
• Thread 1 saves the memory to file
• Thread to reads written file contents (now empty)
• Thread 2 sees that the UUID is empty and returns empty server, so a new server is registered

[AuroraLS3]

Here's a dev build of the above commit, I was unable to reproduce the issue still, but this might fix it regardless Plan-5.4-dev-build-1696.jar.zip PlanFabric-5.4-dev-build-1696.jar.zip

[Thin-Troll]

There were duplicates, but this time I did not find the messages Registering a new server in database with UUID

[Thin-Troll]

using version 1696

[AuroraLS3]

Did you update all servers? 🤔 Note that there's also the possibility of old version leaving behind empty ServerInfoFile.yml for the new version to duplicate one last time

Please let me know if it happens again after this incident

[Thin-Troll]

ok, I'll try again to remove the duplicates and see the result.

[AuroraLS3]

Here's a new build since your screenshot shows that SkyPvP has duplicated again (id 57) despite running newest build Plan-5.4-dev-build-1702.jar.zip

[AuroraLS3]

Reopening due to #2768