Cleanup login handling & reduce the amount of unnecessary logging output on startup

bukkit/src/main/java/me/lucko/luckperms/bukkit/BukkitListener.java

@@ -74,7 +74,6 @@ public class BukkitListener implements Listener {
         /* the player was denied entry to the server before this priority.
            log this, so we can handle appropriately later. */
         if (e.getLoginResult() != AsyncPlayerPreLoginEvent.Result.ALLOWED) {
-            plugin.getLog().warn("Connection from " + e.getUniqueId() + " was already denied. No permissions data will be loaded.");
             deniedAsyncLogin.add(e.getUniqueId());
             return;
         }
@@ -89,7 +88,7 @@ public class BukkitListener implements Listener {
             deniedAsyncLogin.add(e.getUniqueId());
 
             // actually deny the connection.
-            plugin.getLog().warn("Permissions storage is not loaded yet. Denying connection from: " + e.getUniqueId() + " - " + e.getName());
+            plugin.getLog().warn("Permissions storage is not loaded. Denying connection from: " + e.getUniqueId() + " - " + e.getName());
             e.disallow(AsyncPlayerPreLoginEvent.Result.KICK_OTHER, Message.LOADING_ERROR.asString(plugin.getLocaleManager()));
             return;
         }
@@ -121,6 +120,7 @@ public class BukkitListener implements Listener {
 
         // Check to see if this connection was denied at LOW.
         if (deniedAsyncLogin.remove(e.getUniqueId())) {
+            // their data was never loaded at LOW priority, now check to see if they have been magically allowed since then.
 
             // This is a problem, as they were denied at low priority, but are now being allowed.
             if (e.getLoginResult() == AsyncPlayerPreLoginEvent.Result.ALLOWED) {
@@ -131,7 +131,7 @@ public class BukkitListener implements Listener {
             return;
         }
 
-        // Login event was cancelled by another plugin
+        // Login event was cancelled by another plugin, but it wasn't cancelled when we handled it at LOW
         if (e.getLoginResult() != AsyncPlayerPreLoginEvent.Result.ALLOWED) {
             // Schedule cleanup of this user.
             plugin.getUserManager().scheduleUnload(e.getUniqueId());
@@ -147,7 +147,6 @@ public class BukkitListener implements Listener {
         /* the player was denied entry to the server before this priority.
            log this, so we can handle appropriately later. */
         if (e.getResult() != PlayerLoginEvent.Result.ALLOWED) {
-            plugin.getLog().warn("Login from " + e.getPlayer().getUniqueId() + " was denied before an attachment could be injected.");
             deniedLogin.add(e.getPlayer().getUniqueId());
             return;
         }
@@ -190,20 +189,20 @@ public class BukkitListener implements Listener {
         /* Listen to see if the event was cancelled after we initially handled the login
            If the connection was cancelled here, we need to do something to clean up the data that was loaded. */
 
-        // Check to see if this connection was denied at LOW.
+        // Check to see if this connection was denied at LOW. Even if it was denied at LOW, their data will still be present.
+        boolean denied = false;
         if (deniedLogin.remove(e.getPlayer().getUniqueId())) {
+            denied = true;
 
             // This is a problem, as they were denied at low priority, but are now being allowed.
             if (e.getResult() == PlayerLoginEvent.Result.ALLOWED) {
                 plugin.getLog().severe("Player connection was re-allowed for " + e.getPlayer().getUniqueId());
                 e.disallow(PlayerLoginEvent.Result.KICK_OTHER, "");
             }
-
-            return;
         }
 
-        // Login event was cancelled by another plugin
+        // Login event was cancelled by another plugin since we first loaded their data
-        if (e.getResult() != PlayerLoginEvent.Result.ALLOWED) {
+        if (denied || e.getResult() != PlayerLoginEvent.Result.ALLOWED) {
             // Schedule cleanup of this user.
             plugin.getUserManager().scheduleUnload(e.getPlayer().getUniqueId());
             return;
@@ -236,8 +235,7 @@ public class BukkitListener implements Listener {
             return;
         }
 
-        String s = e.getMessage().toLowerCase()
+        String s = e.getMessage().substring(1).toLowerCase()
-                .replace("/", "")
                 .replace("bukkit:", "")
                 .replace("spigot:", "")
                 .replace("minecraft:", "");

bukkit/src/main/java/me/lucko/luckperms/bukkit/LPBukkitPlugin.java

@@ -192,9 +192,8 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
         }, 1L);
 
         // register events
-        PluginManager pm = getServer().getPluginManager();
         listener = new BukkitListener(this);
-        pm.registerEvents(listener, this);
+        getServer().getPluginManager().registerEvents(listener, this);
 
         if (getConfiguration().get(ConfigKeys.WATCH_FILES)) {
             fileWatcher = new FileWatcher(this);
@@ -209,14 +208,16 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
         if (messagingType.equals("none") && getConfiguration().get(ConfigKeys.REDIS_ENABLED)) {
             messagingType = "redis";
         }
+
+        if (!messagingType.equals("none")) {
+            getLog().info("Loading messaging service... [" + messagingType.toUpperCase() + "]");
+        }
+
         if (messagingType.equals("redis")) {
-            getLog().info("Loading redis...");
             if (getConfiguration().get(ConfigKeys.REDIS_ENABLED)) {
                 RedisMessaging redis = new RedisMessaging(this);
                 try {
                     redis.init(getConfiguration().get(ConfigKeys.REDIS_ADDRESS), getConfiguration().get(ConfigKeys.REDIS_PASSWORD));
-                    getLog().info("Loaded redis successfully...");
-
                     messagingService = redis;
                 } catch (Exception e) {
                     getLog().warn("Couldn't load redis...");
@@ -226,12 +227,10 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
                 getLog().warn("Messaging Service was set to redis, but redis is not enabled!");
             }
         } else if (messagingType.equals("bungee")) {
-            getLog().info("Loading bungee messaging service...");
             BungeeMessagingService bungeeMessaging = new BungeeMessagingService(this);
             bungeeMessaging.init();
             messagingService = bungeeMessaging;
         } else if (messagingType.equals("lilypad")) {
-            getLog().info("Loading LilyPad messaging service...");
             if (getServer().getPluginManager().getPlugin("LilyPad-Connect") == null) {
                 getLog().warn("LilyPad-Connect plugin not present.");
             } else {
@@ -260,7 +259,7 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
         localeManager = new SimpleLocaleManager();
         File locale = new File(getDataFolder(), "lang.yml");
         if (locale.exists()) {
-            getLog().info("Found locale file. Attempting to load from it.");
+            getLog().info("Found lang.yml - loading messages...");
             try {
                 localeManager.loadFromFile(locale);
             } catch (Exception e) {
@@ -269,7 +268,6 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
         }
 
         // register commands
-        getLog().info("Registering commands...");
         commandManager = new BukkitCommand(this);
         PluginCommand main = getServer().getPluginCommand("luckperms");
         main.setExecutor(commandManager);
@@ -298,7 +296,6 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
         tryVaultHook(false);
 
         // register with the LP API
-        getLog().info("Registering API...");
         apiProvider = new ApiProvider(this);
         ApiHandler.registerProvider(apiProvider);
         getServer().getServicesManager().register(LuckPermsApi.class, apiProvider, this, ServicePriority.Normal);
@@ -313,6 +310,7 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
         scheduler.asyncLater(() -> updateTaskBuffer.request(), 40L);
 
         // run an update instantly.
+        getLog().info("Performing initial data load...");
         updateTaskBuffer.requestDirectly();
 
         // register tasks
@@ -351,7 +349,7 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
             });
         }
 
-        getLog().info("Successfully loaded.");
+        getLog().info("Successfully enabled.");
     }
 
     @Override
@@ -378,7 +376,7 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
             }
         }
 
-        getLog().info("Closing datastore...");
+        getLog().info("Closing storage...");
         storage.shutdown();
 
         if (fileWatcher != null) {
@@ -390,7 +388,6 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
             messagingService.close();
         }
 
-        getLog().info("Unregistering API...");
         ApiHandler.unregisterProvider();
         getServer().getServicesManager().unregisterAll(this);
 
@@ -398,6 +395,7 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
             vaultHook.unhook(this);
         }
 
+        getLog().info("Shutting down internal scheduler...");
         scheduler.shutdown();
 
         // Bukkit will do this again when #onDisable completes, but we do it early to prevent NPEs elsewhere.
@@ -436,9 +434,6 @@ public class LPBukkitPlugin extends JavaPlugin implements LuckPermsPlugin {
             return; // already hooked
         }
 
-        if (force) {
-            getLog().info("Attempting to hook with Vault...");
-        }
         try {
             if (force || getServer().getPluginManager().isPluginEnabled("Vault")) {
                 vaultHook = new VaultHook();

bungee/src/main/java/me/lucko/luckperms/bungee/BungeeListener.java

@@ -78,7 +78,6 @@ public class BungeeListener implements Listener {
         if (e.isCancelled()) {
 
             // log that we are not loading any data
-            plugin.getLog().warn("Connection from " + c.getUniqueId() + " was already denied. No permissions data will be loaded.");
             deniedLogin.add(c.getUniqueId());
 
             e.completeIntent(plugin);
@@ -91,7 +90,7 @@ public class BungeeListener implements Listener {
         if (!plugin.getStorage().isAcceptingLogins()) {
 
             // log that the user tried to login, but was denied at this stage.
-            plugin.getLog().warn("Permissions storage is not loaded yet. No permissions data will be loaded for: " + c.getUniqueId() + " - " + c.getName());
+            plugin.getLog().warn("Permissions storage is not loaded. No permissions data will be loaded for: " + c.getUniqueId() + " - " + c.getName());
             deniedLogin.add(c.getUniqueId());
 
             e.completeIntent(plugin);

bungee/src/main/java/me/lucko/luckperms/bungee/LPBungeePlugin.java

@@ -150,14 +150,16 @@ public class LPBungeePlugin extends Plugin implements LuckPermsPlugin {
         if (messagingType.equals("none") && getConfiguration().get(ConfigKeys.REDIS_ENABLED)) {
             messagingType = "redis";
         }
+
+        if (!messagingType.equals("none")) {
+            getLog().info("Loading messaging service... [" + messagingType.toUpperCase() + "]");
+        }
+
         if (messagingType.equals("redis")) {
-            getLog().info("Loading redis...");
             if (getConfiguration().get(ConfigKeys.REDIS_ENABLED)) {
                 RedisMessaging redis = new RedisMessaging(this);
                 try {
                     redis.init(getConfiguration().get(ConfigKeys.REDIS_ADDRESS), getConfiguration().get(ConfigKeys.REDIS_PASSWORD));
-                    getLog().info("Loaded redis successfully...");
-
                     messagingService = redis;
                 } catch (Exception e) {
                     getLog().warn("Couldn't load redis...");
@@ -167,7 +169,6 @@ public class LPBungeePlugin extends Plugin implements LuckPermsPlugin {
                 getLog().warn("Messaging Service was set to redis, but redis is not enabled!");
             }
         } else if (messagingType.equals("bungee")) {
-            getLog().info("Loading bungee messaging service...");
             BungeeMessagingService bungeeMessaging = new BungeeMessagingService(this);
             bungeeMessaging.init();
             messagingService = bungeeMessaging;
@@ -192,7 +193,7 @@ public class LPBungeePlugin extends Plugin implements LuckPermsPlugin {
         localeManager = new SimpleLocaleManager();
         File locale = new File(getDataFolder(), "lang.yml");
         if (locale.exists()) {
-            getLog().info("Found locale file. Attempting to load from it.");
+            getLog().info("Found lang.yml - loading messages...");
             try {
                 localeManager.loadFromFile(locale);
             } catch (Exception e) {
@@ -201,7 +202,6 @@ public class LPBungeePlugin extends Plugin implements LuckPermsPlugin {
         }
 
         // register commands
-        getLog().info("Registering commands...");
         commandManager = new CommandManager(this);
         getProxy().getPluginManager().registerCommand(this, new BungeeCommand(this, commandManager));
 
@@ -226,7 +226,6 @@ public class LPBungeePlugin extends Plugin implements LuckPermsPlugin {
         contextManager.registerStaticCalculator(staticCalculator);
 
         // register with the LP API
-        getLog().info("Registering API...");
         apiProvider = new ApiProvider(this);
         ApiHandler.registerProvider(apiProvider);
 
@@ -239,18 +238,19 @@ public class LPBungeePlugin extends Plugin implements LuckPermsPlugin {
         scheduler.asyncLater(() -> updateTaskBuffer.request(), 40L);
 
         // run an update instantly.
+        getLog().info("Performing initial data load...");
         updateTaskBuffer.requestDirectly();
 
         // register tasks
         scheduler.asyncRepeating(new ExpireTemporaryTask(this), 60L);
         scheduler.asyncRepeating(new CacheHousekeepingTask(this), 2400L);
 
-        getLog().info("Successfully loaded.");
+        getLog().info("Successfully enabled.");
     }
 
     @Override
     public void onDisable() {
-        getLog().info("Closing datastore...");
+        getLog().info("Closing storage...");
         storage.shutdown();
 
         if (fileWatcher != null) {
@@ -262,9 +262,10 @@ public class LPBungeePlugin extends Plugin implements LuckPermsPlugin {
             messagingService.close();
         }
 
-        getLog().info("Unregistering API...");
         ApiHandler.unregisterProvider();
 
+        getLog().info("Shutting down internal scheduler...");
+        scheduler.shutdown();
         getProxy().getScheduler().cancel(this);
         getProxy().getPluginManager().unregisterListeners(this);
     }

common/src/main/java/me/lucko/luckperms/common/dependencies/DependencyManager.java

@@ -71,8 +71,6 @@ public class DependencyManager {
             .build();
 
     public static void loadDependencies(LuckPermsPlugin plugin, Set<StorageType> storageTypes) {
-        plugin.getLog().info("Loading dependencies...");
-
         List<Dependency> dependencies = new ArrayList<>();
         for (StorageType storageType : storageTypes) {
             dependencies.addAll(STORAGE_DEPENDENCIES.get(storageType));

common/src/main/java/me/lucko/luckperms/common/storage/StorageFactory.java

@@ -52,10 +52,7 @@ import java.util.Set;
 public class StorageFactory {
 
     public static Set<StorageType> getRequiredTypes(LuckPermsPlugin plugin, StorageType defaultMethod) {
-        plugin.getLog().info("Detecting storage method...");
         if (plugin.getConfiguration().get(ConfigKeys.SPLIT_STORAGE)) {
-            plugin.getLog().info("Loading split storage options.");
-
             Map<String, String> types = new HashMap<>(plugin.getConfiguration().get(ConfigKeys.SPLIT_STORAGE_OPTIONS));
             types.entrySet().stream()
                     .filter(e -> StorageType.parse(e.getValue()) == null)
@@ -82,10 +79,8 @@ public class StorageFactory {
 
     public static Storage getInstance(LuckPermsPlugin plugin, StorageType defaultMethod) {
         Storage storage;
-
-        plugin.getLog().info("Initializing storage backings...");
         if (plugin.getConfiguration().get(ConfigKeys.SPLIT_STORAGE)) {
-            plugin.getLog().info("Using split storage.");
+            plugin.getLog().info("Loading storage provider... [SPLIT STORAGE]");
 
             Map<String, String> types = new HashMap<>(plugin.getConfiguration().get(ConfigKeys.SPLIT_STORAGE_OPTIONS));
             types.entrySet().stream()
@@ -110,11 +105,10 @@ public class StorageFactory {
                 type = defaultMethod;
             }
 
-            plugin.getLog().info("Using " + type.getName() + " storage.");
+            plugin.getLog().info("Loading storage provider... [" + type.name() + "]");
             storage = makeInstance(type, plugin);
         }
 
-        plugin.getLog().info("Initialising storage provider...");
         storage.init();
         return storage;
     }

sponge/src/main/java/me/lucko/luckperms/sponge/LPSpongePlugin.java

@@ -201,14 +201,16 @@ public class LPSpongePlugin implements LuckPermsPlugin {
         if (messagingType.equals("none") && getConfiguration().get(ConfigKeys.REDIS_ENABLED)) {
             messagingType = "redis";
         }
+
+        if (!messagingType.equals("none")) {
+            getLog().info("Loading messaging service... [" + messagingType.toUpperCase() + "]");
+        }
+
         if (messagingType.equals("redis")) {
-            getLog().info("Loading redis...");
             if (getConfiguration().get(ConfigKeys.REDIS_ENABLED)) {
                 RedisMessaging redis = new RedisMessaging(this);
                 try {
                     redis.init(getConfiguration().get(ConfigKeys.REDIS_ADDRESS), getConfiguration().get(ConfigKeys.REDIS_PASSWORD));
-                    getLog().info("Loaded redis successfully...");
-
                     messagingService = redis;
                 } catch (Exception e) {
                     getLog().warn("Couldn't load redis...");
@@ -218,7 +220,6 @@ public class LPSpongePlugin implements LuckPermsPlugin {
                 getLog().warn("Messaging Service was set to redis, but redis is not enabled!");
             }
         } else if (messagingType.equals("bungee")) {
-            getLog().info("Loading bungee messaging service...");
             BungeeMessagingService bungeeMessaging = new BungeeMessagingService(this);
             bungeeMessaging.init();
             messagingService = bungeeMessaging;
@@ -243,7 +244,7 @@ public class LPSpongePlugin implements LuckPermsPlugin {
         localeManager = new SimpleLocaleManager();
         File locale = new File(getDataDirectory(), "lang.yml");
         if (locale.exists()) {
-            getLog().info("Found locale file. Attempting to load from it.");
+            getLog().info("Found lang.yml - loading messages...");
             try {
                 localeManager.loadFromFile(locale);
             } catch (Exception e) {
@@ -252,7 +253,6 @@ public class LPSpongePlugin implements LuckPermsPlugin {
         }
 
         // register commands
-        getLog().info("Registering commands...");
         CommandManager cmdService = game.getCommandManager();
         commandManager = new SpongeCommand(this);
         cmdService.register(this, commandManager, "luckperms", "lp", "perm", "perms", "permission", "permissions");
@@ -288,7 +288,6 @@ public class LPSpongePlugin implements LuckPermsPlugin {
         }
 
         // register with the LP API
-        getLog().info("Registering API...");
         apiProvider = new ApiProvider(this);
         ApiHandler.registerProvider(apiProvider);
         game.getServiceManager().setProvider(this, LuckPermsApi.class, apiProvider);
@@ -302,6 +301,7 @@ public class LPSpongePlugin implements LuckPermsPlugin {
         scheduler.asyncLater(() -> updateTaskBuffer.request(), 40L);
 
         // run an update instantly.
+        getLog().info("Performing initial data load...");
         updateTaskBuffer.requestDirectly();
 
         // register tasks
@@ -310,7 +310,7 @@ public class LPSpongePlugin implements LuckPermsPlugin {
         scheduler.asyncRepeating(new ServiceCacheHousekeepingTask(service), 2400L);
         // scheduler.asyncRepeating(() -> userManager.performCleanup(), 2400L);
 
-        getLog().info("Successfully loaded.");
+        getLog().info("Successfully enabled.");
     }
 
     @Listener(order = Order.LATE)
@@ -325,7 +325,7 @@ public class LPSpongePlugin implements LuckPermsPlugin {
 
     @Listener
     public void onDisable(GameStoppingServerEvent event) {
-        getLog().info("Closing datastore...");
+        getLog().info("Closing storage...");
         storage.shutdown();
 
         if (fileWatcher != null) {
@@ -337,9 +337,9 @@ public class LPSpongePlugin implements LuckPermsPlugin {
             messagingService.close();
         }
 
-        getLog().info("Unregistering API...");
         ApiHandler.unregisterProvider();
 
+        getLog().info("Shutting down internal scheduler...");
         scheduler.shutdown();
     }
 

sponge/src/main/java/me/lucko/luckperms/sponge/SpongeListener.java

@@ -75,7 +75,6 @@ public class SpongeListener {
         /* the player was denied entry to the server before this priority.
            log this, so we can handle appropriately later. */
         if (e.isCancelled()) {
-            plugin.getLog().warn("Connection from " + p.getUniqueId() + " was already denied. No permissions data will be loaded.");
             deniedAsyncLogin.add(p.getUniqueId());
             return;
         }
@@ -90,9 +89,9 @@ public class SpongeListener {
             deniedAsyncLogin.add(p.getUniqueId());
 
             // actually deny the connection.
-            plugin.getLog().warn("Permissions storage is not loaded yet. Denying connection from: " + p.getUniqueId() + " - " + p.getName());
+            plugin.getLog().warn("Permissions storage is not loaded. Denying connection from: " + p.getUniqueId() + " - " + p.getName());
             e.setCancelled(true);
-            e.setMessageCancelled(true);
+            e.setMessageCancelled(false);
             //noinspection deprecation
             e.setMessage(TextSerializers.LEGACY_FORMATTING_CODE.deserialize(Message.LOADING_ERROR.asString(plugin.getLocaleManager())));
             return;
@@ -112,8 +111,10 @@ public class SpongeListener {
         } catch (Exception ex) {
             ex.printStackTrace();
 
+            deniedAsyncLogin.add(p.getUniqueId());
+
             e.setCancelled(true);
-            e.setMessageCancelled(true);
+            e.setMessageCancelled(false);
             //noinspection deprecation
             e.setMessage(TextSerializers.LEGACY_FORMATTING_CODE.deserialize(Message.LOADING_ERROR.asString(plugin.getLocaleManager())));
         }
@@ -149,7 +150,6 @@ public class SpongeListener {
             /* the player was denied entry to the server before this priority.
                log this, so we can handle appropriately later. */
             if (e.isCancelled()) {
-                plugin.getLog().warn("Login from " + player.getUniqueId() + " was denied before an attachment could be injected.");
                 deniedLogin.add(player.getUniqueId());
                 return;
             }
@@ -162,7 +162,7 @@ public class SpongeListener {
 
                 plugin.getLog().warn("User " + player.getUniqueId() + " - " + player.getName() + " doesn't have data pre-loaded. - denying login.");
                 e.setCancelled(true);
-                e.setMessageCancelled(true);
+                e.setMessageCancelled(false);
                 //noinspection deprecation
                 e.setMessage(TextSerializers.LEGACY_FORMATTING_CODE.deserialize(Message.LOADING_ERROR.asString(plugin.getLocaleManager())));
                 return;
@@ -192,6 +192,22 @@ public class SpongeListener {
         }
     }
 
+    @Listener(order = Order.BEFORE_POST)
+    @IsCancelled(Tristate.UNDEFINED)
+    public void onClientLoginMonitor(ClientConnectionEvent.Login e) {
+        /* Listen to see if the event was cancelled after we initially handled the login
+           If the connection was cancelled here, we need to do something to clean up the data that was loaded. */
+
+        // Check to see if this connection was denied at LOW. Even if it was denied at LOW, their data will still be present.
+        if (deniedLogin.remove(e.getProfile().getUniqueId())) {
+            // This is a problem, as they were denied at low priority, but are now being allowed.
+            if (!e.isCancelled()) {
+                plugin.getLog().severe("Player connection was re-allowed for " + e.getProfile().getUniqueId());
+                e.setCancelled(true);
+            }
+        }
+    }
+
     @Listener(order = Order.EARLY)
     public void onClientJoin(ClientConnectionEvent.Join e) {
         // Refresh permissions again