Instrumenting proper logging for player actions

config.yml

@@ -3,6 +3,10 @@
 # return is the amount of material to return.
 # percent_chance is the chance to return the block. Scales with damage.
 # scale_amount is, if maturation is enabled, the amount extra to damage a block if it is not fully matured.  The forumla for calculating the extra damage is 1/(1-((time left of maturation) / (default amount of time for maturation))) * scale.  So if a block has 5 minutes left of maturation on a 10 minute default period with a scale of 3 we do 1/(5 / 10) * 3 = 6 damage. Setting scale amount to 0 disables this function.
+internal_logging: true
+command_logging: true
+break_logging: true
+reinf_logging: false
 reinforcements:
  diamond:
   material: DIAMOND

plugin.yml

@@ -29,6 +29,9 @@ commands:
  ctar:
   permission: citadel.admin
   aliases: [ctareareinforce] 
+ ctsl:
+  permission: citadel.admin
+  aliases: [ctsetlogging]
 permissions:
  citadel.admin:
   default: op

pom.xml

@@ -5,7 +5,7 @@
 	<groupId>vg.civcraft.mc.citadel</groupId>
 	<artifactId>Citadel</artifactId>
 	<packaging>jar</packaging>
-	<version>3.4.42</version>
+	<version>3.4.43</version>
 	<name>Citadel</name>
 	<url>https://github.com/Civcraft/Citadel</url>
 
@@ -16,8 +16,8 @@
 					<artifactId>maven-compiler-plugin</artifactId>
 					<version>2.3.2</version>
 					<configuration>
-						<source>1.6</source>
-						<target>1.6</target>
+						<source>1.8</source>
+						<target>1.8</target>
 					</configuration>
 				</plugin>
 			</plugins>

src/vg/civcraft/mc/citadel/Citadel.java

@@ -7,7 +7,6 @@
 import org.bukkit.Bukkit;
 import org.bukkit.command.Command;
 import org.bukkit.command.CommandSender;
-import org.bukkit.configuration.file.FileConfiguration;
 import org.bukkit.plugin.java.JavaPlugin;
 
 import vg.civcraft.mc.citadel.command.CommandHandler;
@@ -22,7 +21,6 @@
 import vg.civcraft.mc.citadel.reinforcementtypes.NaturalReinforcementType;
 import vg.civcraft.mc.citadel.reinforcementtypes.NonReinforceableType;
 import vg.civcraft.mc.citadel.reinforcementtypes.ReinforcementType;
-import vg.civcraft.mc.namelayer.NameLayerPlugin;
 
 public class Citadel extends JavaPlugin{
 	private static Logger logger;

src/vg/civcraft/mc/citadel/CitadelConfigManager.java

@@ -140,4 +140,20 @@ public static String getUserName(){
 	public static String getPassword(){
 		return config.getString("mysql.password", "");
 	}
+
+	public static boolean shouldLogInternal() {
+		return config.getBoolean("internal_logging", false);
+	}
+
+	public static boolean shouldLogPlayerCommands() {
+		return config.getBoolean("command_logging", false);
+	}
+
+	public static boolean shouldLogBreaks() {
+		return config.getBoolean("break_logging", false);
+	}
+
+	public static boolean shouldLogReinforcement() {
+		return config.getBoolean("reinf_logging", false);
+	}
 }

src/vg/civcraft/mc/citadel/PlayerState.java

@@ -3,6 +3,7 @@
 import java.util.HashMap;
 import java.util.Map;
 import java.util.UUID;
+import java.util.logging.Level;
 
 import org.bukkit.Bukkit;
 import org.bukkit.ChatColor;
@@ -26,6 +27,9 @@ public class PlayerState {
      * @return The PlayerState of that player.
      */
     public static PlayerState get(Player player) {
+    	if (player == null) {
+    		Citadel.getInstance().getLogger().log(Level.WARNING, "PlayerState get called with null player");
+    	}
         UUID id = NameAPI.getUUID(player.getName());
         PlayerState state = PLAYER_STATES.get(id);
         if (state == null) {
@@ -36,6 +40,9 @@ public static PlayerState get(Player player) {
     }
 
     public static PlayerState get(UUID id) {
+    	if (id == null) {
+    		Citadel.getInstance().getLogger().log(Level.WARNING, "PlayerState get called with null id");
+    	}
     	PlayerState state = PLAYER_STATES.get(id);
         if (state == null) {
             state = new PlayerState(id);
@@ -54,7 +61,6 @@ public static void remove(Player player) {
 
     private UUID accountId;
     private ReinforcementMode mode;
-    private Material fortificationMaterial;
     private Group faction;
     private boolean bypassMode;
     private Integer cancelModePid;
@@ -75,7 +81,6 @@ public PlayerState(UUID uuid) {
      */
     public void reset() {
         mode = ReinforcementMode.NORMAL;
-        fortificationMaterial = null;
         fortificationStack = null;
         faction = null;
     }
@@ -99,7 +104,9 @@ public void setMode(ReinforcementMode mode) {
      * @param ItemStack.
      */
     public void setFortificationItemStack(ItemStack fortificationStack) {
-        this.fortificationMaterial = fortificationStack.getType();
+    	if (fortificationStack == null) {
+    		Citadel.getInstance().getLogger().log(Level.WARNING, "PlayerState setFortificationItemStack called with null stack");
+    	}
         this.fortificationStack = fortificationStack;
     }
     /**
@@ -114,6 +121,9 @@ public Group getGroup() {
      * @param The group.
      */
     public void setGroup(Group faction) {
+    	if (faction == null) {
+    		Citadel.getInstance().getLogger().log(Level.WARNING, "PlayerState setGroup called with null faction");
+    	}
         this.faction = faction;
     }
     /**
@@ -146,11 +156,15 @@ public void checkResetMode() {
 
         cancelModePid = scheduler.scheduleSyncDelayedTask(plugin, new Runnable() {
             public void run() {
-                Player player = Bukkit.getPlayer(accountId);
-                if (player != null) {
-                    player.sendMessage(ChatColor.YELLOW + mode.name() + " mode off");
-                }
-                reset();
+            	try {
+	                Player player = Bukkit.getPlayer(accountId);
+	                if (player != null) {
+	                    player.sendMessage(ChatColor.YELLOW + mode.name() + " mode off");
+	                }
+	                reset();
+            	} catch (Exception e) {
+               		Citadel.getInstance().getLogger().log(Level.WARNING, "PlayerState checkResetMode Failed", e);
+            	}
             }
         }, 20L * CitadelConfigManager.getPlayerStateReset());
     }

src/vg/civcraft/mc/citadel/ReinforcementManager.java

@@ -4,6 +4,7 @@
 import java.util.List;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.TimeUnit;
+import java.util.logging.Level;
 
 import com.google.common.cache.CacheBuilder;
 import com.google.common.cache.CacheLoader;
@@ -29,22 +30,27 @@ public class ReinforcementManager {
 
 	// This shit is cool
 	private RemovalListener<Location, Reinforcement> removalListener = new RemovalListener<Location, Reinforcement>() {
-		public void onRemoval(
-				RemovalNotification<Location, Reinforcement> removal) {
+		public void onRemoval(RemovalNotification<Location, Reinforcement> removal) {
 			Reinforcement rein = removal.getValue();
-			if (rein instanceof NullReinforcement){
+			if (rein == null || rein instanceof NullReinforcement){
 				return;
 			}
-			if (rein.isDirty())
+			if (rein.isDirty()) {
 				saveReinforcement(rein);
+			}
 		}
 	};
+
 	private LoadingCache<Location, Reinforcement> reinforcements = CacheBuilder
 			.newBuilder().maximumSize(CitadelConfigManager.getMaxCacheSize())
 			.expireAfterAccess(CitadelConfigManager.getMaxCacheMinutes(), TimeUnit.MINUTES)
 			.removalListener(removalListener)
 			.build(new CacheLoader<Location, Reinforcement>() {
 				public Reinforcement load(Location loc) throws Exception {
+					if (loc == null) {
+						Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager cache load called with null");
+					}
+
 					Reinforcement rein = db.getReinforcement(loc);
 					if (rein == null) {
 						return new NullReinforcement(loc);
@@ -73,8 +79,13 @@ public long getDayMultiplier(){
 	 * @param The Reinforcement to save
 	 */
 	public void saveReinforcement(Reinforcement rein) {
-		if (rein.getDurability() <= 0)
+		if (rein == null) {
+			Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager saveReinforcement called with null");
+			return;
+		}
+		if (rein.getDurability() <= 0) {
 			deleteReinforcement(rein);
+		}
 		CitadelStatics.updateHitStat(CitadelStatics.UPDATE);
 		db.saveReinforcement(rein);
 		rein.setDirty(false);
@@ -88,6 +99,10 @@ public void saveInitialReinforcement(Reinforcement rein) {
 		// Do a check first, there might be an edge case for example half slabs where there is a reinforcement
 		// but it got this far.  Lets just keep the one already there and ignore this new one.
 		// If this is some other case then the code already in place should have deleted the reinforcement EX: Air.
+		if (rein == null) {
+			Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager saveInitialReinforcement called with null");
+			return;
+		}
 		if (getReinforcement(rein.getLocation()) == null) {
 			reinforcements.put(rein.getLocation(), rein);
 			CitadelStatics.updateHitStat(CitadelStatics.INSERT);
@@ -102,15 +117,23 @@ public void saveInitialReinforcement(Reinforcement rein) {
 	 * @return Reinforcement
 	 */
 	public Reinforcement getReinforcement(Location loc) {
+		if (loc == null) {
+			Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager getReinforcement called with null");
+			return null;
+		}
+
 		try {
 			Reinforcement rein = reinforcements.get(loc);
-			if (rein instanceof NullReinforcement)
+			if (rein instanceof NullReinforcement) {
 				return null;
+			}
 			CitadelStatics.updateHitStat(CitadelStatics.CACHE);
 			return rein;
 		} catch (Exception e) {
-			if (!(e.getCause() instanceof LoadingCacheNullException))
+			// So we ignore cache errors?
+			if (!(e.getCause() instanceof LoadingCacheNullException)) {
 				e.printStackTrace();
+			}
 		}
 		return null;
 	}
@@ -122,6 +145,10 @@ public Reinforcement getReinforcement(Location loc) {
 	 * @return Reinforcement
 	 */
 	public Reinforcement getReinforcement(Block block) {
+		if (block == null) {
+			Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager getReinforcement block called with null");
+			return null;
+		}
 		return getReinforcement(block.getLocation());
 	}
 
@@ -132,6 +159,10 @@ public Reinforcement getReinforcement(Block block) {
 	 * @param rein
 	 */
 	public void deleteReinforcement(Reinforcement rein) {
+		if (rein == null) {
+			Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager deleteReinforcement called with null");
+			return;
+		}
 		reinforcements.invalidate(rein.getLocation());
 		CitadelStatics.updateHitStat(CitadelStatics.DELETE);
 		db.deleteReinforcement(rein);
@@ -153,6 +184,11 @@ public void invalidateAllReinforcements() {
 	 * @return Returns true if one was found.
 	 */
 	public boolean isReinforced(Location loc) {
+		if (loc == null) {
+			Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager isReinforced called with null");
+			return false;
+		}
+
 		return getReinforcement(loc) != null;
 	}
 
@@ -164,6 +200,11 @@ public boolean isReinforced(Location loc) {
 	 * @return Returns true if one was found.
 	 */
 	public boolean isReinforced(Block block) {
+		if (block == null) {
+			Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager isReinforced block called with null");
+			return false;
+		}
+
 		return isReinforced(block.getLocation());
 	}
 
@@ -173,12 +214,34 @@ private void scheduleSave(){
 
 			@Override
 			public void run() {
-				List<Reinforcement> reins = new ArrayList<Reinforcement>();
-				for (Reinforcement r: reinforcements.asMap().values())
-					reins.add(r);
-				for (Reinforcement r: reins) {
-					if (r.isDirty())
+				try {
+					long cached = 0l;
+					long dirty = 0l;
+					long s = 0l;
+					if (CitadelConfigManager.shouldLogInternal()) {
+						Citadel.Log("Running Scheduled Save");
+						s = System.currentTimeMillis();
+					}
+					List<Reinforcement> reins = new ArrayList<Reinforcement>();
+					synchronized(reinforcements){
+						for (Reinforcement r: reinforcements.asMap().values()) {
+							if (r.isDirty()) {
+								reins.add(r);
+								dirty++;
+							}
+							cached++;
+						}
+					}
+					for (Reinforcement r: reins) {
 						saveReinforcement(r);
+					}
+					if (CitadelConfigManager.shouldLogInternal()) {
+						s = System.currentTimeMillis() - s;
+						Citadel.Log("Scheduled Save complete in " + s + " ms. Cache holds " +
+							cached + " entries, " + dirty + " entries saved to DB.");
+					}
+				} catch (Exception e) {
+					Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager scheduled save encountered a problem", e);
 				}
 			}
 
@@ -191,6 +254,11 @@ public void run() {
 	 * Then returns the list of reinforcements in the Chunk.
 	 */
 	public List<Reinforcement> getReinforcementsByChunk(Chunk chunk){
+		if (chunk == null) {
+			Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager getReinforcementsByChunk called with null");
+			return new ArrayList<Reinforcement>();
+		}
+
 		List<Reinforcement> reins = db.getReinforcements(chunk);
 		List<Reinforcement> reins_new = new ArrayList<Reinforcement>();
 		for (Reinforcement rein: reins){
@@ -203,8 +271,7 @@ public List<Reinforcement> getReinforcementsByChunk(Chunk chunk){
 				try {
 					r = reinforcements.get(rein.getLocation());
 				} catch (ExecutionException e) {
-					// TODO Auto-generated catch block
-					e.printStackTrace();
+					Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager getReinforcementsByChunk called with null", e);
 				}
 				reins_new.add(r);
 			}
@@ -213,6 +280,10 @@ public List<Reinforcement> getReinforcementsByChunk(Chunk chunk){
 	}
 
 	public void loadReinforcementChunk(Chunk chunk) {
+		if (chunk == null) {
+			Citadel.getInstance().getLogger().log(Level.WARNING, "ReinforcementManager loadReinforcementChunk called with null");
+			return;
+		}
 		List<Reinforcement> reins = db.getReinforcements(chunk);
 		for (Reinforcement rein: reins){
 			Reinforcement r = reinforcements.getIfPresent(rein.getLocation());