Add debug logging to ConfigFileApplicationListener

Update ConfigFileApplicationListener to include more debug level output.
Debug messages are recorded during onApplicationEnvironmentPreparedEvent
but not actually output until onApplicationPreparedEvent. This is
because the logging level might not have been correctly set until the
context is completely prepared.

Fixes gh-1584

Author: philwebb

spring-boot/src/main/java/org/springframework/boot/context/config/ConfigFileApplicationListener.java

@@ -27,6 +27,8 @@
 import java.util.Queue;
 import java.util.Set;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 import org.springframework.beans.BeansException;
 import org.springframework.beans.factory.config.BeanFactoryPostProcessor;
 import org.springframework.beans.factory.config.ConfigurableListableBeanFactory;
@@ -106,6 +108,8 @@ public class ConfigFileApplicationListener implements
 
 	public static final int DEFAULT_ORDER = Ordered.HIGHEST_PRECEDENCE + 10;
 
+	private static Log logger = LogFactory.getLog(ConfigFileApplicationListener.class);
+
 	private String searchLocations;
 
 	private String names;
@@ -114,6 +118,8 @@ public class ConfigFileApplicationListener implements
 
 	private final ConversionService conversionService = new DefaultConversionService();
 
+	private final List<Object> debug = new ArrayList<Object>();
+
 	@Override
 	public void onApplicationEvent(ApplicationEvent event) {
 		if (event instanceof ApplicationEnvironmentPreparedEvent) {
@@ -140,9 +146,21 @@ private void onApplicationEnvironmentPreparedEvent(
 	}
 
 	private void onApplicationPreparedEvent(ApplicationPreparedEvent event) {
+		logDebugMessages();
 		addPostProcessors(event.getApplicationContext());
 	}
 
+	private void logDebugMessages() {
+		// Debug logging is deferred because the Logging initialization might not have
+		// run at the time that config file decisions are taken
+		if (logger.isDebugEnabled()) {
+			for (Object message : this.debug) {
+				logger.debug(message);
+			}
+		}
+		this.debug.clear();
+	}
+
 	/**
 	 * Add config file property sources to the specified environment.
 	 * @param environment the environment to add source to
@@ -270,6 +288,8 @@ private class Loader {
 
 		private boolean activatedProfiles;
 
+		private final List<Object> debug = ConfigFileApplicationListener.this.debug;
+
 		public Loader(ConfigurableEnvironment environment, ResourceLoader resourceLoader) {
 			this.environment = environment;
 			this.resourceLoader = resourceLoader == null ? new DefaultResourceLoader()
@@ -280,7 +300,6 @@ public void load() throws IOException {
 			this.propertiesLoader = new PropertySourcesLoader();
 			this.profiles = Collections.asLifoQueue(new LinkedList<String>());
 			this.activatedProfiles = false;
-
 			if (this.environment.containsProperty(ACTIVE_PROFILES_PROPERTY)) {
 				// Any pre-existing active profiles set via property sources (e.g. System
 				// properties) take precedence over those added in config files.
@@ -354,29 +373,46 @@ private void load(String location, String name, String profile)
 		private PropertySource<?> loadIntoGroup(String identifier, String location,
 				String profile) throws IOException {
 			Resource resource = this.resourceLoader.getResource(location);
+			PropertySource<?> propertySource = null;
 			if (resource != null) {
 				String name = "applicationConfig: [" + location + "]";
 				String group = "applicationConfig: [" + identifier + "]";
-				PropertySource<?> propertySource = this.propertiesLoader.load(resource,
-						group, name, profile);
+				propertySource = this.propertiesLoader.load(resource, group, name,
+						profile);
 				if (propertySource != null) {
 					maybeActivateProfiles(propertySource
 							.getProperty(ACTIVE_PROFILES_PROPERTY));
 					addIncludeProfiles(propertySource
 							.getProperty(INCLUDE_PROFILES_PROPERTY));
 				}
-				return propertySource;
 			}
-			return null;
+
+			StringBuilder msg = new StringBuilder();
+			msg.append(propertySource == null ? "Skipped " : "Loaded ");
+			msg.append("config file ");
+			msg.append("'" + location + "' ");
+			msg.append(StringUtils.hasLength(profile) ? "for profile " : "");
+			msg.append(resource == null || !resource.exists() ? "resource not found" : "");
+			this.debug.add(msg);
+
+			return propertySource;
 		}
 
 		private void maybeActivateProfiles(Object value) {
-			if (!this.activatedProfiles == true) {
-				Set<String> profiles = getProfilesForValue(value);
-				activateProfiles(profiles);
-				if (profiles.size() > 0) {
-					this.activatedProfiles = true;
+			if (this.activatedProfiles) {
+				if (value != null) {
+					this.debug.add("Profiles already activated, '" + value
+							+ "' will not be applied");
 				}
+				return;
+			}
+
+			Set<String> profiles = getProfilesForValue(value);
+			activateProfiles(profiles);
+			if (profiles.size() > 0) {
+				this.debug.add("Activated profiles "
+						+ StringUtils.collectionToCommaDelimitedString(profiles));
+				this.activatedProfiles = true;
 			}
 		}
 

spring-boot/src/main/java/org/springframework/boot/context/config/RandomValuePropertySource.java

@@ -18,6 +18,8 @@
 
 import java.util.Random;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 import org.springframework.core.env.ConfigurableEnvironment;
 import org.springframework.core.env.PropertySource;
 import org.springframework.core.env.StandardEnvironment;
@@ -33,6 +35,8 @@
  */
 public class RandomValuePropertySource extends PropertySource<Random> {
 
+	private static Log logger = LogFactory.getLog(RandomValuePropertySource.class);
+
 	public RandomValuePropertySource(String name) {
 		super(name, new Random());
 	}
@@ -42,6 +46,9 @@ public Object getProperty(String name) {
 		if (!name.startsWith("random.")) {
 			return null;
 		}
+		if (logger.isTraceEnabled()) {
+			logger.trace("Generating random property for '" + name + "'");
+		}
 		if (name.endsWith("int")) {
 			return getSource().nextInt();
 		}
@@ -71,6 +78,7 @@ public static void addToEnvironment(ConfigurableEnvironment environment) {
 		environment.getPropertySources().addAfter(
 				StandardEnvironment.SYSTEM_ENVIRONMENT_PROPERTY_SOURCE_NAME,
 				new RandomValuePropertySource("random"));
+		logger.trace("RandomValuePropertySource add to Environment");
 	}
 
 }