improving the use of java util Logging

springloaded/src/main/java/org/springsource/loaded/CurrentLiveVersion.java

@@ -69,7 +69,7 @@ public class CurrentLiveVersion {
 		this.typeDescriptor = reloadableType.getTypeRegistry().getExtractor().extract(newbytedata, true);
 		this.versionstamp = versionstamp;
 
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			if (!this.typeDescriptor.getName().equals(reloadableType.typedescriptor.getName())) {
 				throw new IllegalStateException("New version has wrong name.  Expected " + reloadableType.typedescriptor.getName()
 						+ " but was " + typeDescriptor.getName());

springloaded/src/main/java/org/springsource/loaded/GlobalConfiguration.java

@@ -59,6 +59,11 @@ public class GlobalConfiguration {
 	 */
 	public static boolean verboseMode = false;
 	
+	/**
+	 * asserts mode will trigger extra checking (performance impact but confirms correctness)
+	 */
+	public static boolean assertsMode = false;
+	
 	/**
 	 * Can be turned on to enable users to determine the decision process around why
 	 * something is not reloadable.
@@ -97,7 +102,6 @@ public class GlobalConfiguration {
 	/**
 	 * Global control for checking assertions
 	 */
-	public final static boolean assertsOn = false;
 	public final static boolean isProfiling = false;
 
 	public static boolean directlyDefineTypes = true;
@@ -247,7 +251,11 @@ public class GlobalConfiguration {
 						} else if (key.equals("verbose")) {
 							verboseMode = kv.substring(equals + 1).equalsIgnoreCase("true");
 							reloadMessages = verboseMode;
-						} else if (key.equals("rebasePaths")) {
+						}
+						else if (key.equals("asserts")) {
+							assertsMode = kv.substring(equals + 1).equalsIgnoreCase("true");
+						}
+						else if (key.equals("rebasePaths")) {
 							// value is a series of "a=b,c=d,e=f" indicating from and to
 							globalConfigurationProperties.put("rebasePaths", kv.substring(equals + 1));
 						} else if (key.equals("inclusions")) {
@@ -270,6 +278,11 @@ public class GlobalConfiguration {
 						else if (kv.equals("verbose")) {
 							Log.log("[verbose mode on] Full configuration is:"+value);
 							verboseMode = true;
+							reloadMessages = true;
+						}
+						else if (kv.equals("asserts")) {
+							Log.log("[asserts mode on] Will verify system coherence");
+							assertsMode = true;
 						}
 						else if (kv.equals("explain")) {
 							Log.log("[explain mode on] Reporting on the decision making process within SpringLoaded");

springloaded/src/main/java/org/springsource/loaded/ReloadableType.java

@@ -139,7 +139,7 @@ public class ReloadableType {
 	 */
 	public ReloadableType(String dottedtypename, byte[] initialBytes, int id, TypeRegistry typeRegistry,
 			TypeDescriptor typeDescriptor) {
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			Utils.assertDotted(dottedtypename);
 		}
 		this.id = id;

springloaded/src/main/java/org/springsource/loaded/TypePattern.java

@@ -24,7 +24,7 @@ package org.springsource.loaded;
 public abstract class TypePattern {
 
 	public boolean matches(String dottedname) {
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			Utils.assertDotted(dottedname);
 		}
 		return internalMatches(dottedname);

springloaded/src/main/java/org/springsource/loaded/TypeRegistry.java

@@ -553,7 +553,7 @@ public class TypeRegistry {
 	 */
 	private List<String> packagesFound = new ArrayList<String>();
 	private List<String> packagesNotFound = new ArrayList<String>();
-
+	
 	/**
 	 * Determine if the named type could be reloadable. This method is invoked if the user has not setup any inclusions. With no
 	 * inclusions specified, something is considered reloadable if it is accessible by the classloader for this registry and is not
@@ -672,7 +672,7 @@ public class TypeRegistry {
 		if (GlobalConfiguration.verboseMode && log.isLoggable(Level.FINER)) {
 			log.finer("entering TypeRegistry.isReloadableTypeName(" + slashedName + ")");
 		}
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			Utils.assertSlashed(slashedName);
 		}
 		if (GlobalConfiguration.isProfiling) {
@@ -901,7 +901,7 @@ public class TypeRegistry {
 
 		String slashname = dottedname.replace('.', '/');
 		reloadableTypeDescriptorCache.put(slashname, td);
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			Utils.assertTrue(td.getName().equals(slashname), "Name from bytecode '" + td.getName()
 					+ "' does not match that passed in '" + slashname + "'");
 		}

springloaded/src/main/java/org/springsource/loaded/Utils.java

@@ -134,7 +134,7 @@ public class Utils implements Opcodes, Constants {
 			}
 		} else {
 			// either array or reference type
-			if (GlobalConfiguration.assertsOn) {
+			if (GlobalConfiguration.assertsMode) {
 				// Must not end with a ';' unless it starts with a '['
 				if (returnType.descriptor.endsWith(";") && !returnType.descriptor.startsWith("[")) {
 					throw new IllegalArgumentException("Invalid signature of '" + returnType.descriptor + "'");
@@ -734,7 +734,7 @@ public class Utils implements Opcodes, Constants {
 	 * @return the byte data defining that class
 	 */
 	public static byte[] loadDottedClassAsBytes(ClassLoader loader, String dottedclassname) {
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			if (dottedclassname.endsWith(".class")) {
 				throw new IllegalStateException(".class suffixed name should not be passed:" + dottedclassname);
 			}
@@ -758,7 +758,7 @@ public class Utils implements Opcodes, Constants {
 	 * @return the byte data defining that class
 	 */
 	public static byte[] loadSlashedClassAsBytes(ClassLoader loader, String slashedclassname) {
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			if (slashedclassname.endsWith(".class")) {
 				throw new IllegalStateException(".class suffixed name should not be passed:" + slashedclassname);
 			}
@@ -856,7 +856,7 @@ public class Utils implements Opcodes, Constants {
 	 * @return new version of input descriptor with first parameter taken out
 	 */
 	public static String stripFirstParameter(String descriptor) {
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			if (descriptor.indexOf(';') == -1) {
 				throw new IllegalStateException("Input descriptor must have at least one parameter: " + descriptor);
 			}
@@ -907,7 +907,7 @@ public class Utils implements Opcodes, Constants {
 		 */
 		private ReturnType(String descriptor, Kind kind) {
 			this.descriptor = descriptor;
-			if (GlobalConfiguration.assertsOn) {
+			if (GlobalConfiguration.assertsMode) {
 				if (this.kind == Kind.REFERENCE) {
 					if (descriptor.endsWith(";") && !descriptor.startsWith("[")) {
 						throw new IllegalStateException("Should already have been stripped of 'L' and ';': " + descriptor);
@@ -976,7 +976,7 @@ public class Utils implements Opcodes, Constants {
 					return ReturnType.getReturnType(withoutLeadingLorTrailingSemi, Kind.REFERENCE);
 				} else {
 					// must be an array!
-					if (GlobalConfiguration.assertsOn) {
+					if (GlobalConfiguration.assertsMode) {
 						Utils.assertTrue(ch == '[', "Expected array leading char: " + descriptor);
 					}
 					return ReturnType.getReturnType(descriptor, Kind.ARRAY);
@@ -1074,7 +1074,7 @@ public class Utils implements Opcodes, Constants {
 	 * @return the path to the file
 	 */
 	public static String dump(String slashname, byte[] bytesLoaded) {
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			if (slashname.indexOf('.') != -1) {
 				throw new IllegalStateException("Slashed type name expected, not '" + slashname + "'");
 			}
@@ -1504,7 +1504,7 @@ public class Utils implements Opcodes, Constants {
 	 * @return the result we can return, or null if it is not compatible
 	 */
 	public static Object checkCompatibility(TypeRegistry registry, Object result, String expectedTypeDescriptor) {
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			Utils.assertTrue(result != null, "result should never be null");
 		}
 		String actualType = result.getClass().getName();

springloaded/src/main/java/org/springsource/loaded/agent/CglibPlugin.java

@@ -16,7 +16,10 @@
 package org.springsource.loaded.agent;
 
 import java.security.ProtectionDomain;
+import java.util.logging.Level;
+import java.util.logging.Logger;
 
+import org.springsource.loaded.GlobalConfiguration;
 import org.springsource.loaded.LoadtimeInstrumentationPlugin;
 
 
@@ -28,27 +31,29 @@ import org.springsource.loaded.LoadtimeInstrumentationPlugin;
  */
 public class CglibPlugin implements LoadtimeInstrumentationPlugin {
 
-//		private static Logger log = Logger.getLogger(CglibPlugin.class.getName());
+	private static Logger log = Logger.getLogger(CglibPlugin.class.getName());
 
 	// implementing LoadtimeInstrumentationPlugin
 	public boolean accept(String slashedTypeName, ClassLoader classLoader, ProtectionDomain protectionDomain, byte[] bytes) {
 		if (slashedTypeName==null) {
 			return false;
 		}
-//		if (slashedTypeName.contains("cglib")) {
-//			System.out.println(">>CglibPlugin.accept("+slashedTypeName+")");
-//		}
-		// Seen in the wild:
+		// Sometimes the package prefix for cglib types is changed, for example:
 		// net/sf/cglib/core/AbstractClassGenerator
 		// org/springframework/cglib/core/AbstractClassGenerator
+		// This test will allow for both variants
 		return slashedTypeName.endsWith("/cglib/core/AbstractClassGenerator");
 		// || slashedTypeName.equals("net/sf/cglib/reflect/FastClass");
 	}
 
 	public byte[] modify(String slashedClassName, ClassLoader classLoader, byte[] bytes) {
-		System.out.println(">> CglibPlugin.modify("+slashedClassName+","+classLoader+","+bytes.length);
+		if (GlobalConfiguration.verboseMode && log.isLoggable(Level.INFO)) {
+			log.info("Modifying "+slashedClassName);
+		}
 		// if (slashedClassName.equals("net/sf/cglib/core/AbstractClassGenerator")) {
 		return CglibPluginCapturing.catchGenerate(bytes);
+		
+		// Not currently worrying about FastClass:
 		// } else {
 		// net/sf/cglib/reflect/FastClass
 		// We must empty the FastClass constructor.  Why?  Due to current limitations with

springloaded/src/main/java/org/springsource/loaded/agent/FileSystemWatcher.java

@@ -105,7 +105,6 @@ class Watcher implements Runnable {
 	private static long interval = 1100;// ms
 	List<File> watchListFiles = new ArrayList<File>();
 	List<Long> watchListLMTs = new ArrayList<Long>();
-	//	Map<File, Long> watchList = new ConcurrentHashMap<File, Long>();
 	FileChangeListener listener;
 	private boolean timeToStop = false;
 	public boolean paused = false;
@@ -137,6 +136,9 @@ class Watcher implements Runnable {
 			return false;
 		}
 		synchronized (this) {
+			if (GlobalConfiguration.verboseMode && log.isLoggable(Level.INFO)) {
+				log.info("Now watching "+fileToWatch);
+			}
 			int insertionPos = findPosition(fileToWatch);
 			if (insertionPos == -1) {
 				watchListFiles.add(fileToWatch);
@@ -169,6 +171,12 @@ class Watcher implements Runnable {
 			if (cmp > 0) {
 				return f;
 			}
+			else if (GlobalConfiguration.assertsMode && cmp == 0) {
+				// Are we watching the same file twice, that is bad!
+				if (file2.getAbsoluteFile().toString().equals(file.getAbsoluteFile().toString())) {
+					log.severe("Watching the same file twice: "+file.getAbsoluteFile().toString());
+				}
+			}
 		}
 		return -1;
 	}
@@ -179,10 +187,10 @@ class Watcher implements Runnable {
 			if ((registryLivenessCount % registryLivenessCountInterval) == 0) {
 				// Time to check if the registry is still alive!
 				if (!TypeRegistry.typeRegistryExistsForId(typeRegistryId)) {
-					//					System.out.println("TypeRegistry " + typeRegistryId + " gone, no point in thread continuing!");
+					if (GlobalConfiguration.verboseMode && log.isLoggable(Level.INFO)) {
+						log.info("TypeRegistry " + typeRegistryId + " gone, no point in thread continuing!");
+					}
 					return;
-					//				} else {
-					//					System.out.println("TypeRegistry " + typeRegistryId + " seems to still be around!");
 				}
 				registryLivenessCount = 0;
 			}
@@ -198,7 +206,9 @@ class Watcher implements Runnable {
 						File file = watchListFiles.get(f);
 						long lastModTime = file.lastModified();
 						if (lastModTime > watchListLMTs.get(f)) {
-							// System.out.println("Watcher: " + lastScanTime + " change detected in " + file);
+							if (GlobalConfiguration.verboseMode && log.isLoggable(Level.INFO)) {
+								log.info("Observed last modification time change for "+file+" (lastScanTime="+lastScanTime+")");
+							}
 							watchListLMTs.set(f, lastModTime);
 							changedFiles.add(file);
 						}
@@ -219,6 +229,9 @@ class Watcher implements Runnable {
 
 	private void determineChangesSince(File file, long lastScanTime) {
 		try {
+			if (GlobalConfiguration.verboseMode && log.isLoggable(Level.INFO)) {
+				log.info("Firing file changed event "+file);
+			}
 			listener.fileChanged(file);
 			if (file.isDirectory()) {
 				File[] filesOfInterest = file.listFiles(new RecentChangeFilter(lastScanTime));
@@ -227,14 +240,17 @@ class Watcher implements Runnable {
 						determineChangesSince(f, lastScanTime);
 					} else {
 						if (GlobalConfiguration.verboseMode && log.isLoggable(Level.INFO)) {
-							log.info("file change observed: "+f);
+							log.info("Observed last modification time change for "+f+"  (lastScanTime="+lastScanTime+")");
+							log.info("Firing file changed event "+file);
 						}
 						listener.fileChanged(f);
 					}
 				}
 			}
 		} catch (Throwable t) {
-			new RuntimeException("FileWatcher caught serious error, see cause.", t).printStackTrace();
+			if (log.isLoggable(Level.SEVERE)) {
+				log.log(Level.SEVERE,"FileWatcher caught serious error, see cause",t);
+			}
 		}
 	}
 

springloaded/src/main/java/org/springsource/loaded/agent/ReloadableFileChangeListener.java

@@ -45,7 +45,7 @@ public class ReloadableFileChangeListener implements FileChangeListener {
 
 	public void fileChanged(File file) {
 		if (GlobalConfiguration.isRuntimeLogging && log.isLoggable(Level.INFO)) {
-			log.info("ReloadableFileChangeListener: change detected in " + file);
+			log.info(" processing change for " + file);
 		}
 		ReloadableType rtype = correspondingReloadableTypes.get(file);
 		typeRegistry.loadNewVersion(rtype, file);

springloaded/src/main/java/org/springsource/loaded/ri/FieldLookup.java

@@ -126,7 +126,7 @@ public class FieldLookup {
 		private FieldMember f;
 
 		public ReloadedTypeFieldRef(ReloadableType rtype, FieldMember f) {
-			if (GlobalConfiguration.assertsOn) {
+			if (GlobalConfiguration.assertsMode) {
 				Utils.assertTrue(rtype.hasBeenReloaded(), "Not yet reloaded: " + rtype.getName());
 			}
 			this.rtype = rtype;

springloaded/src/main/java/org/springsource/loaded/ri/ReflectiveInterceptor.java

@@ -1600,7 +1600,7 @@ public class ReflectiveInterceptor {
 					}
 					fields[i++] = JVM.newField(clazz, type, f.getModifiers(), f.getName(), f.getGenericSignature());
 				}
-				if (GlobalConfiguration.assertsOn) {
+				if (GlobalConfiguration.assertsMode) {
 					Utils.assertTrue(i == fields.length, "Bug: unexpected number of fields");
 				}
 				return fields;
@@ -1623,7 +1623,7 @@ public class ReflectiveInterceptor {
 		if (i < realFields.length) {
 			realFields = Utils.arrayCopyOf(realFields, i);
 		}
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			Utils.assertTrue(i == realFields.length, "Bug in removeMetaFields, created array of wrong length");
 		}
 		return realFields;

springloaded/src/main/java/org/springsource/loaded/ri/ReloadableTypeMethodProvider.java

@@ -40,7 +40,7 @@ public class ReloadableTypeMethodProvider extends TypeDescriptorMethodProvider {
 	ReloadableType rtype;
 
 	public ReloadableTypeMethodProvider(ReloadableType rtype) {
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			Utils.assertTrue(rtype != null, "ReloadableTypeMethodProvider rtype should not be null");
 		}
 		this.rtype = rtype;

springloaded/src/main/java/org/springsource/loaded/ri/ReloadedTypeInvoker.java

@@ -42,7 +42,7 @@ public abstract class ReloadedTypeInvoker extends Invoker {
 	private ReloadedTypeInvoker(ReloadableTypeMethodProvider declaringType, MethodMember methodMember) {
 		this.methodMember = methodMember;
 		rtype = declaringType.getRType();
-		if (GlobalConfiguration.assertsOn) {
+		if (GlobalConfiguration.assertsMode) {
 			Utils.assertTrue(rtype.hasBeenReloaded(),
 					"This class is only equiped to provide invocation/method services for reloaded types");
 		}