From 10c11c180c00117d3f64914c8c2cdddde557e6ba Mon Sep 17 00:00:00 2001 From: John Blum Date: Wed, 5 Aug 2020 15:30:58 -0700 Subject: [PATCH] Add new Spring ApplicationListener implementation to log the state of the Spring Environment consistently across contexts as needed. The EnvironmentLoggingApplicationListener is automattically registered with the Spring Boot configured list of ApplicationListeners via the (SpringFactories) SPI. --- ...EnvironmentLoggingApplicationListener.java | 237 ++++++++++++++ .../main/resources/META-INF/spring.factories | 3 +- ...ntLoggingApplicationListenerUnitTests.java | 303 ++++++++++++++++++ 3 files changed, 542 insertions(+), 1 deletion(-) create mode 100644 spring-geode/src/main/java/org/springframework/geode/context/logging/EnvironmentLoggingApplicationListener.java create mode 100644 spring-geode/src/test/java/org/springframework/geode/context/logging/EnvironmentLoggingApplicationListenerUnitTests.java diff --git a/spring-geode/src/main/java/org/springframework/geode/context/logging/EnvironmentLoggingApplicationListener.java b/spring-geode/src/main/java/org/springframework/geode/context/logging/EnvironmentLoggingApplicationListener.java new file mode 100644 index 00000000..d5dc7fca --- /dev/null +++ b/spring-geode/src/main/java/org/springframework/geode/context/logging/EnvironmentLoggingApplicationListener.java @@ -0,0 +1,237 @@ +/* + * Copyright 2020 the original author or authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express + * or implied. See the License for the specific language governing + * permissions and limitations under the License. + */ +package org.springframework.geode.context.logging; + +import java.util.Arrays; +import java.util.Map; +import java.util.Optional; +import java.util.TreeMap; +import java.util.function.Function; + +import org.springframework.context.ApplicationListener; +import org.springframework.context.event.ContextRefreshedEvent; +import org.springframework.core.env.ConfigurableEnvironment; +import org.springframework.core.env.EnumerablePropertySource; +import org.springframework.core.env.Environment; +import org.springframework.core.env.PropertySource; +import org.springframework.data.gemfire.util.CollectionUtils; +import org.springframework.lang.NonNull; +import org.springframework.lang.Nullable; +import org.springframework.util.ObjectUtils; +import org.springframework.util.StringUtils; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +/** + * Spring {@link ApplicationListener} used to log the state of the Spring {@link Environment} + * on the {@link ContextRefreshedEvent}. + * + * @author John Blum + * @see org.slf4j.Logger + * @see org.slf4j.LoggerFactory + * @see org.springframework.context.ApplicationListener + * @see org.springframework.context.event.ContextRefreshedEvent + * @see org.springframework.core.env.Environment + * @see org.springframework.core.env.PropertySource + * @since 1.4.0 + */ +@SuppressWarnings("unused") +public class EnvironmentLoggingApplicationListener implements ApplicationListener { + + protected static final String SYSTEM_ERR_ENABLED_PROPERTY = + "spring.context.environment.logging.system-err.enabled"; + + static final ThreadLocal threadLocalEnvironmentReference = new ThreadLocal<>(); + + private final Logger logger = LoggerFactory.getLogger(getClass()); + + /** + * @inheritDoc + */ + @Override + public void onApplicationEvent(@NonNull ContextRefreshedEvent contextRefreshedEvent) { + + Environment environment = contextRefreshedEvent.getApplicationContext().getEnvironment(); + + threadLocalEnvironmentReference.set(environment); + + try { + log("ENV: [%s]", ObjectUtils.nullSafeClassName(environment)); + log("ENV: Active Profiles %s", Arrays.toString(environment.getActiveProfiles())); + log("ENV: Default Profiles %s", Arrays.toString(environment.getDefaultProfiles())); + + if (environment instanceof ConfigurableEnvironment) { + + ConfigurableEnvironment configurableEnvironment = (ConfigurableEnvironment) environment; + + for (PropertySource propertySource : configurableEnvironment.getPropertySources()) { + log("ENV: PropertySource [%s]", propertySource.getName()); + getCompositePropertySourceLoggingFunction().apply(propertySource); + } + } + } + finally { + threadLocalEnvironmentReference.remove(); + } + } + + /** + * Returns a {@literal Composite} {@link Function} capable of introspecting and logging properties + * from specifically typed {@link PropertySource PropertySources}. + * + * @return a {@literal Composite} {@link Function} capable of introspecting and logging the properties + * from specifically typed {@link PropertySource PropertySources}. + * @see org.springframework.core.env.PropertySource + * @see java.util.function.Function + */ + protected Function, PropertySource> getCompositePropertySourceLoggingFunction() { + return new EnumerablePropertySourceLoggingFunction().andThen(new MapPropertySourceLoggingFunction()); + } + + /** + * Gets a reference to the configured SLF4J {@link Logger}. + * + * @return a reference to the configured SLF4J {@link Logger}. + * @see org.slf4j.Logger + */ + protected @NonNull Logger getLogger() { + return this.logger; + } + + /** + * Logs the given {@link String message} formatted with the given array of {@link Object arguments} + * to the configured Spring Boot application log. + * + * The given {@link String message} will only be logged if it contains text, otherwise this method does nothing + * and silently returns. + * + * @param message {@link String} containing the message to log. + * @param args optional array of {@link Object arguments} to apply when formatting the {@link String message}. + * @see #logToSlf4jLogger(String, Object...) + * @see #logToSystemErr(String, Object...) + */ + protected void log(String message, Object... args) { + + if (StringUtils.hasText(message)) { + logToSlf4jLogger(message, args); + logToSystemErr(message, args); + } + } + + /** + * Logs the given {@link String message} to the configured SLF4J {@link Logger}. + * + * @param message {@link String} containing the message to log. + * @param args optional array of {@link Object arguments} to apply when formatting the {@link String message}. + * @see #getLogger() + */ + void logToSlf4jLogger(String message, Object... args) { + //getLogger().debug(String.format(message, args), args); + getLogger().debug(String.format(message, args)); + } + + /** + * Logs the given {@link String message} to {@link System#err}. + * + * This logging method is available to perform poor mans logging when explicit SLF4J {@link Logger} configuration + * was not provided in the deployed Spring Boot application. However, in most cases, this logging method should not + * be used and proper SLF4J {@link Logger} configuration should be provided in most cases. + * + * This logging option is only enabled when the {@literal spring.context.environment.logging.system-err.enabled} + * property is set to {@literal true}. + * + * @param message {@link String} containing the message to log. + * @param args optional array of {@link Object arguments} to apply when formatting the {@link String message}. + */ + void logToSystemErr(String message, Object... args) { + + if (isSystemErrLoggingEnabled()) { + message = message.trim().endsWith("%n") ? message : message.concat("%n"); + System.err.printf(message, args); + System.err.flush(); + } + } + + private boolean isSystemErrLoggingEnabled() { + + return Optional.ofNullable(threadLocalEnvironmentReference.get()) + .map(environment -> environment.getProperty(SYSTEM_ERR_ENABLED_PROPERTY, Boolean.class, false)) + .orElseGet(() -> Boolean.getBoolean(SYSTEM_ERR_ENABLED_PROPERTY)); + } + + protected abstract class AbstractPropertySourceLoggingFunction + implements Function, PropertySource> { + + protected void logProperties(@NonNull Iterable propertyNames, + @NonNull Function propertyValueFunction) { + + log("Properties ["); + + for (String propertyName : CollectionUtils.nullSafeIterable(propertyNames)) { + log("\t%1$s = %2$s", propertyName, propertyValueFunction.apply(propertyName)); + } + + log("]"); + } + } + + protected class EnumerablePropertySourceLoggingFunction extends AbstractPropertySourceLoggingFunction { + + @Override + public @Nullable PropertySource apply(@Nullable PropertySource propertySource) { + + if (propertySource instanceof EnumerablePropertySource) { + + EnumerablePropertySource enumerablePropertySource = + (EnumerablePropertySource) propertySource; + + String[] propertyNames = enumerablePropertySource.getPropertyNames(); + + Arrays.sort(propertyNames); + + logProperties(Arrays.asList(propertyNames), enumerablePropertySource::getProperty); + } + + return propertySource; + } + } + + // The PropertySource may not be enumerable but may use a Map as its source. + protected class MapPropertySourceLoggingFunction extends AbstractPropertySourceLoggingFunction { + + @Override + @SuppressWarnings("unchecked") + public @Nullable PropertySource apply(@Nullable PropertySource propertySource) { + + if (!(propertySource instanceof EnumerablePropertySource)) { + + Object source = propertySource != null + ? propertySource.getSource() + : null; + + if (source instanceof Map) { + + Map map = new TreeMap<>((Map) source); + + logProperties(map.keySet(), map::get); + } + } + + return propertySource; + } + } +} diff --git a/spring-geode/src/main/resources/META-INF/spring.factories b/spring-geode/src/main/resources/META-INF/spring.factories index bd284d8a..80b396ba 100644 --- a/spring-geode/src/main/resources/META-INF/spring.factories +++ b/spring-geode/src/main/resources/META-INF/spring.factories @@ -1,3 +1,4 @@ # Spring Boot for Apache Geode Application Listeners org.springframework.context.ApplicationListener=\ -org.springframework.geode.context.logging.GeodeLoggingApplicationListener +org.springframework.geode.context.logging.GeodeLoggingApplicationListener,\ +org.springframework.geode.context.logging.EnvironmentLoggingApplicationListener diff --git a/spring-geode/src/test/java/org/springframework/geode/context/logging/EnvironmentLoggingApplicationListenerUnitTests.java b/spring-geode/src/test/java/org/springframework/geode/context/logging/EnvironmentLoggingApplicationListenerUnitTests.java new file mode 100644 index 00000000..f1241876 --- /dev/null +++ b/spring-geode/src/test/java/org/springframework/geode/context/logging/EnvironmentLoggingApplicationListenerUnitTests.java @@ -0,0 +1,303 @@ +/* + * Copyright 2020 the original author or authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express + * or implied. See the License for the specific language governing + * permissions and limitations under the License. + */ +package org.springframework.geode.context.logging; + +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.anyString; +import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.Mockito.doNothing; +import static org.mockito.Mockito.doReturn; +import static org.mockito.Mockito.inOrder; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.spy; +import static org.mockito.Mockito.times; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.verifyNoInteractions; +import static org.mockito.Mockito.verifyNoMoreInteractions; + +import java.io.PrintStream; +import java.util.Collections; +import java.util.Map; + +import org.junit.Test; +import org.mockito.InOrder; + +import org.springframework.context.ApplicationContext; +import org.springframework.context.event.ContextRefreshedEvent; +import org.springframework.core.env.ConfigurableEnvironment; +import org.springframework.core.env.Environment; +import org.springframework.core.env.MutablePropertySources; +import org.springframework.core.env.PropertySource; +import org.springframework.data.gemfire.util.ArrayUtils; +import org.springframework.mock.env.MockEnvironment; +import org.springframework.mock.env.MockPropertySource; + +import org.slf4j.Logger; + +/** + * Unit Tests for {@link EnvironmentLoggingApplicationListener}. + * + * @author John Blum + * @see java.io.PrintStream + * @see org.junit.Test + * @see org.mockito.Mockito + * @see org.slf4j.Logger + * @see org.springframework.context.ApplicationContext + * @see org.springframework.context.event.ContextRefreshedEvent + * @see org.springframework.core.env.ConfigurableEnvironment + * @see org.springframework.core.env.Environment + * @see org.springframework.core.env.PropertySource + * @see org.springframework.geode.context.logging.EnvironmentLoggingApplicationListener + * @see org.springframework.mock.env.MockEnvironment + * @see org.springframework.mock.env.MockPropertySource + * @since 1.4.0 + */ +public class EnvironmentLoggingApplicationListenerUnitTests { + + @Test + @SuppressWarnings("unchecked") + public void onApplicationEventLogsEnvironmentStateCorrectly() { + + ApplicationContext mockApplicationContext = mock(ApplicationContext.class); + + ConfigurableEnvironment mockEnvironment = new MockEnvironment(); + + ContextRefreshedEvent mockEvent = mock(ContextRefreshedEvent.class); + + Logger mockLogger = mock(Logger.class); + + MutablePropertySources propertySources = mockEnvironment.getPropertySources(); + + propertySources.remove(MockPropertySource.MOCK_PROPERTIES_PROPERTY_SOURCE_NAME); + + mockEnvironment = spy(mockEnvironment); + + doReturn(mockApplicationContext).when(mockEvent).getApplicationContext(); + doReturn(mockEnvironment).when(mockApplicationContext).getEnvironment(); + + doReturn(ArrayUtils.asArray("activeOne","activeTwo", "activeThree")) + .when(mockEnvironment).getActiveProfiles(); + + doReturn(ArrayUtils.asArray("defaultOne","defaultTwo", "defaultThree")) + .when(mockEnvironment).getDefaultProfiles(); + + MockPropertySource mockPropertySourceOne = spy(new MockPropertySource("MockPropertySourceOne") + .withProperty("one", 1) + .withProperty("two", 2)); + + PropertySource> mockPropertySourceTwo = + mock(PropertySource.class, "MockPropertySourceTwo"); + + doReturn("MockPropertySourceTwo").when(mockPropertySourceTwo).getName(); + doReturn(Collections.singletonMap("three", 3)).when(mockPropertySourceTwo).getSource(); + + PropertySource mockPropertySourceThree = mock(PropertySource.class, "MockPropertySourceThree"); + + doReturn("MockPropertySourceThree").when(mockPropertySourceThree).getName(); + + propertySources.addLast(mockPropertySourceOne); + propertySources.addLast(mockPropertySourceTwo); + propertySources.addLast(mockPropertySourceThree); + + EnvironmentLoggingApplicationListener listener = spy(new EnvironmentLoggingApplicationListener()); + + doReturn(mockLogger).when(listener).getLogger(); + doNothing().when(listener).logToSystemErr(anyString(), any()); + + listener.onApplicationEvent(mockEvent); + + InOrder order = inOrder(mockApplicationContext, mockEnvironment, mockEvent, mockLogger, + mockPropertySourceOne, mockPropertySourceTwo, mockPropertySourceThree); + + order.verify(mockEvent, times(1)).getApplicationContext(); + order.verify(mockApplicationContext, times(1)).getEnvironment(); + //order.verify(listener, times(1)).log(eq("ENV: [%s]"), eq(mockEnvironment.getClass().getName())); + order.verify(mockLogger, times(1)) + .debug(eq("ENV: [" + mockEnvironment.getClass().getName() + "]")); + order.verify(mockEnvironment, times(1)).getActiveProfiles(); + order.verify(mockLogger, times(1)) + .debug(eq("ENV: Active Profiles [activeOne, activeTwo, activeThree]")); + order.verify(mockEnvironment, times(1)).getDefaultProfiles(); + order.verify(mockLogger, times(1)) + .debug(eq("ENV: Default Profiles [defaultOne, defaultTwo, defaultThree]")); + order.verify(mockEnvironment, times(1)).getPropertySources(); + order.verify(mockPropertySourceOne, times(1)).getName(); + order.verify(mockLogger, times(1)) + .debug(eq("ENV: PropertySource [MockPropertySourceOne]")); + order.verify(mockPropertySourceOne, times(1)).getPropertyNames(); + order.verify(mockLogger, times(1)).debug(eq("Properties [")); + order.verify(mockPropertySourceOne, times(1)).getProperty(eq("one")); + order.verify(mockLogger, times(1)).debug(eq("\tone = 1")); + order.verify(mockPropertySourceOne, times(1)).getProperty(eq("two")); + order.verify(mockLogger, times(1)).debug(eq("\ttwo = 2")); + order.verify(mockLogger, times(1)).debug(eq("]")); + order.verify(mockPropertySourceTwo, times(1)).getName(); + order.verify(mockLogger, times(1)) + .debug(eq("ENV: PropertySource [MockPropertySourceTwo]")); + order.verify(mockPropertySourceTwo, times(1)).getSource(); + order.verify(mockLogger, times(1)).debug(eq("Properties [")); + order.verify(mockLogger, times(1)).debug(eq("\tthree = 3")); + order.verify(mockLogger, times(1)).debug(eq("]")); + order.verify(mockPropertySourceThree, times(1)).getName(); + order.verify(mockLogger, times(1)) + .debug("ENV: PropertySource [MockPropertySourceThree]"); + order.verify(mockPropertySourceThree, times(1)).getSource(); + + verifyNoMoreInteractions(mockEvent, mockApplicationContext, mockEnvironment, + mockPropertySourceOne, mockPropertySourceTwo, mockPropertySourceThree, mockLogger); + } + + @Test + public void onApplicationEventWithNonConfigurableEnvironmentLogsState() { + + ApplicationContext mockApplicationContext = mock(ApplicationContext.class); + + ContextRefreshedEvent mockEvent = mock(ContextRefreshedEvent.class); + + Environment mockEnvironment = mock(Environment.class); + + doReturn(mockApplicationContext).when(mockEvent).getApplicationContext(); + doReturn(mockEnvironment).when(mockApplicationContext).getEnvironment(); + doReturn(ArrayUtils.asArray("mockProfile")).when(mockEnvironment).getActiveProfiles(); + doReturn(ArrayUtils.asArray("testProfile")).when(mockEnvironment).getDefaultProfiles(); + + Logger mockLogger = mock(Logger.class); + + EnvironmentLoggingApplicationListener listener = spy(new EnvironmentLoggingApplicationListener()); + + doReturn(mockLogger).when(listener).getLogger(); + doNothing().when(listener).logToSystemErr(anyString(), any()); + + listener.onApplicationEvent(mockEvent); + + verify(mockEvent, times(1)).getApplicationContext(); + verify(mockApplicationContext, times(1)).getEnvironment(); + verify(mockLogger, times(1)) + .debug(eq("ENV: [" + mockEnvironment.getClass().getName() + "]")); + verify(mockEnvironment, times(1)).getActiveProfiles(); + verify(mockLogger, times(1)).debug(eq("ENV: Active Profiles [mockProfile]")); + verify(mockEnvironment, times(1)).getDefaultProfiles(); + verify(mockLogger, times(1)).debug(eq("ENV: Default Profiles [testProfile]")); + + verifyNoMoreInteractions(mockApplicationContext, mockEnvironment, mockEvent, mockLogger); + } + + @Test + public void logCallsLogToSlf4jLoggerAndThenLogToSystemErr() { + + EnvironmentLoggingApplicationListener listener = spy(new EnvironmentLoggingApplicationListener()); + + doNothing().when(listener).logToSlf4jLogger(anyString(), any()); + doNothing().when(listener).logToSystemErr(anyString(), any()); + + listener.log("test", 1, 2); + + InOrder order = inOrder(listener); + + order.verify(listener, times(1)) + .logToSlf4jLogger(eq("test"), eq(1), eq(2)); + + order.verify(listener, times(1)) + .logToSystemErr(eq("test"), eq(1), eq(2)); + } + + @Test + public void logDoesNothingWhenLogMessageIsEmpty() { + + EnvironmentLoggingApplicationListener listener = spy(new EnvironmentLoggingApplicationListener()); + + doNothing().when(listener).logToSlf4jLogger(anyString(), any()); + doNothing().when(listener).logToSystemErr(anyString(), any()); + + listener.log(" ", 1, 2); + + InOrder order = inOrder(listener); + + order.verify(listener, never()).logToSlf4jLogger(anyString(), any()); + order.verify(listener, never()).logToSystemErr(anyString(), any()); + } + + @Test + public void logToSystemErrorDoesNothingWhenNotEnabled() { + + Environment mockEnvironment = mock(Environment.class); + + doReturn(false) + .when(mockEnvironment).getProperty(eq(EnvironmentLoggingApplicationListener.SYSTEM_ERR_ENABLED_PROPERTY), + eq(Boolean.class), eq(false)); + + PrintStream mockPrintStream = mock(PrintStream.class); + PrintStream sysErr = System.err; + + EnvironmentLoggingApplicationListener listener = spy(new EnvironmentLoggingApplicationListener()); + + try { + EnvironmentLoggingApplicationListener.threadLocalEnvironmentReference.set(mockEnvironment); + System.setErr(mockPrintStream); + + listener.logToSystemErr("test", 1); + + verify(mockEnvironment, times(1)) + .getProperty(eq(EnvironmentLoggingApplicationListener.SYSTEM_ERR_ENABLED_PROPERTY), + eq(Boolean.class), eq(false)); + verifyNoMoreInteractions(mockEnvironment); + verifyNoInteractions(mockPrintStream); + } + finally { + EnvironmentLoggingApplicationListener.threadLocalEnvironmentReference.remove(); + System.setErr(sysErr); + } + } + + @Test + public void logsToSystemErrOnlyWhenEnabled() { + + Environment mockEnvironment = mock(Environment.class); + + doReturn(true) + .when(mockEnvironment).getProperty(eq(EnvironmentLoggingApplicationListener.SYSTEM_ERR_ENABLED_PROPERTY), + eq(Boolean.class), eq(false)); + + PrintStream mockPrintStream = mock(PrintStream.class); + PrintStream sysErr = System.err; + + EnvironmentLoggingApplicationListener listener = spy(new EnvironmentLoggingApplicationListener()); + + try { + EnvironmentLoggingApplicationListener.threadLocalEnvironmentReference.set(mockEnvironment); + System.setErr(mockPrintStream); + + listener.logToSystemErr("test", 1); + + verify(mockEnvironment, times(1)) + .getProperty(eq(EnvironmentLoggingApplicationListener.SYSTEM_ERR_ENABLED_PROPERTY), + eq(Boolean.class), eq(false)); + + verify(mockEnvironment, times(1)) + .getProperty(eq(EnvironmentLoggingApplicationListener.SYSTEM_ERR_ENABLED_PROPERTY), + eq(Boolean.class), eq(false)); + verify(mockPrintStream, times(1)).printf(eq("test%n"), eq(1)); + verify(mockPrintStream, times(1)).flush(); + + verifyNoMoreInteractions(mockEnvironment, mockPrintStream); + } + finally { + EnvironmentLoggingApplicationListener.threadLocalEnvironmentReference.remove(); + System.setErr(sysErr); + } + } +}