Option to log exceptions related to parameter store retrieval failures

[typekpb]

Type: Bug

Component:
Parameter store

Describe the bug
having issues on retrieval of the parameter store vals results in the following log entry:

15:14:21.641 [main] ERROR org.springframework.boot.diagnostics.LoggingFailureAnalysisReporter - 

***************************
APPLICATION FAILED TO START
***************************

Description:

Config data resource '[AwsParamStoreConfigDataResource@1dc3502b context = '/test-app_testprofile/', optional = false]' via location 'aws-parameterstore:' does not exist

Action:

Check that the value 'aws-parameterstore:' at class path resource [application-testprofile.properties] - 46:22 is correct, or prefix it with 'optional:'

which gives no hint on the exception itself, that hapenned internally.

The swallowed exception:

org.springframework.boot.context.config.ConfigDataResourceNotFoundException: Config data resource '[AwsParamStoreConfigDataResource@1dc3502b context = '/test-app_testprofile/', optional = false]' via location 'aws-parameterstore:' cannot be found
	at org.springframework.boot.context.config.ConfigDataResourceNotFoundException.withLocation(ConfigDataResourceNotFoundException.java:97)
	at org.springframework.boot.context.config.ConfigDataImporter.handle(ConfigDataImporter.java:145)
	at org.springframework.boot.context.config.ConfigDataImporter.load(ConfigDataImporter.java:136)
	at org.springframework.boot.context.config.ConfigDataImporter.resolveAndLoad(ConfigDataImporter.java:86)
	at org.springframework.boot.context.config.ConfigDataEnvironmentContributors.withProcessedImports(ConfigDataEnvironmentContributors.java:116)
	at org.springframework.boot.context.config.ConfigDataEnvironment.processWithProfiles(ConfigDataEnvironment.java:311)
	at org.springframework.boot.context.config.ConfigDataEnvironment.processAndApply(ConfigDataEnvironment.java:232)
	at org.springframework.boot.context.config.ConfigDataEnvironmentPostProcessor.postProcessEnvironment(ConfigDataEnvironmentPostProcessor.java:102)
	at org.springframework.boot.context.config.ConfigDataEnvironmentPostProcessor.postProcessEnvironment(ConfigDataEnvironmentPostProcessor.java:94)
	at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEnvironmentPreparedEvent(EnvironmentPostProcessorApplicationListener.java:102)
	at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEvent(EnvironmentPostProcessorApplicationListener.java:87)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
	at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:85)
	at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:66)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:120)
	at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:114)
	at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:65)
	at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:343)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:301)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1303)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1292)
	at foo.Application.main(Application.java:12)
Caused by: io.awspring.cloud.paramstore.AwsParamStorePropertySources$AwsParameterPropertySourceNotFoundException: com.amazonaws.SdkClientException: Unable to execute HTTP request: Connect to localhost:4566 [localhost/127.0.0.1, localhost/0:0:0:0:0:0:0:1] failed: Connection refused (Connection refused)
	at io.awspring.cloud.paramstore.AwsParamStorePropertySources.createPropertySource(AwsParamStorePropertySources.java:105)
	at io.awspring.cloud.autoconfigure.paramstore.AwsParamStoreConfigDataLoader.load(AwsParamStoreConfigDataLoader.java:55)
	at io.awspring.cloud.autoconfigure.paramstore.AwsParamStoreConfigDataLoader.load(AwsParamStoreConfigDataLoader.java:41)
	at org.springframework.boot.context.config.ConfigDataLoaders.load(ConfigDataLoaders.java:107)
	at org.springframework.boot.context.config.ConfigDataImporter.load(ConfigDataImporter.java:128)
	... 23 more
Caused by: com.amazonaws.SdkClientException: Unable to execute HTTP request: Connect to localhost:4566 [localhost/127.0.0.1, localhost/0:0:0:0:0:0:0:1] failed: Connection refused (Connection refused)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.handleRetryableException(AmazonHttpClient.java:1219)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHttpClient.java:1165)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpClient.java:814)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(AmazonHttpClient.java:781)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpClient.java:755)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttpClient.java:715)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(AmazonHttpClient.java:697)
	at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:561)
	at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:541)
	at com.amazonaws.services.simplesystemsmanagement.AWSSimpleSystemsManagementClient.doInvoke(AWSSimpleSystemsManagementClient.java:11083)
	at com.amazonaws.services.simplesystemsmanagement.AWSSimpleSystemsManagementClient.invoke(AWSSimpleSystemsManagementClient.java:11050)
	at com.amazonaws.services.simplesystemsmanagement.AWSSimpleSystemsManagementClient.invoke(AWSSimpleSystemsManagementClient.java:11039)
	at com.amazonaws.services.simplesystemsmanagement.AWSSimpleSystemsManagementClient.executeGetParametersByPath(AWSSimpleSystemsManagementClient.java:6653)
	at com.amazonaws.services.simplesystemsmanagement.AWSSimpleSystemsManagementClient.getParametersByPath(AWSSimpleSystemsManagementClient.java:6622)
	at io.awspring.cloud.paramstore.AwsParamStorePropertySource.getParameters(AwsParamStorePropertySource.java:69)
	at io.awspring.cloud.paramstore.AwsParamStorePropertySource.init(AwsParamStorePropertySource.java:55)
	at io.awspring.cloud.paramstore.AwsParamStorePropertySources.createPropertySource(AwsParamStorePropertySources.java:99)
	... 27 more
Caused by: org.apache.http.conn.HttpHostConnectException: Connect to localhost:4566 [localhost/127.0.0.1, localhost/0:0:0:0:0:0:0:1] failed: Connection refused (Connection refused)
	at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:156)
	at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:376)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at com.amazonaws.http.conn.ClientConnectionManagerFactory$Handler.invoke(ClientConnectionManagerFactory.java:76)
	at com.amazonaws.http.conn.$Proxy11.connect(Unknown Source)
	at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:393)
	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:236)
	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)
	at com.amazonaws.http.apache.client.impl.SdkHttpClient.execute(SdkHttpClient.java:72)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeOneRequest(AmazonHttpClient.java:1346)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHttpClient.java:1157)
	... 42 more
Caused by: java.net.ConnectException: Connection refused (Connection refused)
	at java.base/java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.base/java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:412)
	at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:255)
	at java.base/java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:237)
	at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
	at java.base/java.net.Socket.connect(Socket.java:609)
	at org.apache.http.conn.socket.PlainConnectionSocketFactory.connectSocket(PlainConnectionSocketFactory.java:75)
	at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:142)
	... 58 more

Workaround
I see the exception only in debug mode (running locally). For the AWS run I had to introduce the AOP Aspect :

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;

@Aspect
public class LogAspect {
    @AfterThrowing(value = "execution(* *(..))", throwing = "e")
    public void log(JoinPoint thisJoinPoint, Throwable e) {
        System.out.println(thisJoinPoint + " -> " + e);
        e.printStackTrace();
    }
}

[maciejwalkowiak]

@typekpb thanks for reporting, would you like to contribute a PR?

[tekener]

As a workaround you could also use the optional setting. In this case there is a log statement inside the ParameterStorePropertySources:

spring:
  config:
    import: 'optional:aws-parameterstore:/config/'

[zhemaituk]

I've encountered the same.
It looks related to #165, possibly a regression, possibly due to some changes in Spring Boot itself.

After debugging it a bit, here is what seems to be happening:

• ParameterStorePropertySources uses DeferredLog for all the logging
• ParameterStorePropertySources throws an Exception which gets caught upstream by spring
• EnvironmentPostProcessorApplicationListener kicks in and drains all the loggers by calling DeferredLogs#switchOverAll, essentially into void
• LoggingApplicationListener kicks in and calls loggingSystem#cleanUp, effectively enabling logging to console. But all the deferred logs where flushed into nowhere already.
• LoggingFailureAnalysisReporter prints "APPLICATION FAILED TO START" with a bit of details. It would print the exception as well, if debug level was enabled, but it's challenging to enable debug in such case as it was failure during configuration init causing spring to just use fallback logging config.

[regrog]

Workaround
I see the exception only in debug mode (running locally). For the AWS run I had to introduce the AOP Aspect :

Hello, I'm facing login problems with spring-cloud-aws-starter-parameter-store version 3.2.1 and can't access the param store.
I's hard to understand what's going on in AWS and it's worst without logs.
Can you explain how to apply your workaround please?

Hoping this issue will be solved soon.

Thanks

[zhemaituk]

To have rootcause printed I ended up adding logback.xml to classpath (src/resources) with content:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
    </root>

    <!-- Presence of logback.xml is a workaround of https://github.com/spring-projects/spring-boot/issues/40930 to print details on failure. -->
    <logger name="org.springframework.boot.diagnostics.LoggingFailureAnalysisReporter" level="DEBUG"/>
</configuration>

aws.ssm.config should not be optional to get an exception on startup.