[BUG] Feature flags and key changes not refreshed on triggered app config update in azure-spring-cloud-starter-appconfiguration-config 2.1.0

[PbALpi7xEX]

Describe the bug
App configuration not refreshing with trigger key and refresh interval.

To Reproduce
Steps to reproduce the behavior:

Code Snippet
Implemented the following config in my bootstrap.properties:

spring.cloud.azure.appconfiguration.stores[0].monitoring.enabled=true
spring.cloud.azure.appconfiguration.stores[0].monitoring.refresh-interval=5s
spring.cloud.azure.appconfiguration.stores[0].monitoring.triggers[0].key=app.config.refreshTrigger
spring.cloud.azure.appconfiguration.stores[0].feature-flags.enabled=true
spring.cloud.azure.appconfiguration.stores[0].monitoring.feature-flags.watch-interval=5s
spring.cloud.azure.appconfiguration.stores[0].selects[0].label-filter=,default,${spring.profiles.active}
spring.cloud.azure.appconfiguration.stores[0].feature-flags.label-filter=,default,${spring.profiles.active}
spring.cloud.azure.appconfiguration.stores[0].fail-fast=true

Feature Flag check in code:

if (Boolean.TRUE.equals(featureManager.isEnabledAsync(FeatureFlags.READ_ONLY_MODE.name()).block())) {
			throw new ApplicationInReadOnlyModeException("Application in read-only mode!");
}

Expected behavior
Toggle a feature, but it is not picked up in code. App restart required for changes to apply.

Setup (please complete the following information):

• OS: Windows 10
• IDE: Eclipse
• Library/Libraries: org.springframework.boot:spring-boot-starter-parent:2.5.2, com.azure.spring:azure-spring-cloud-starter-appconfiguration-config:2.1.0, com.azure.spring:azure-spring-boot-bom:3.7.0
• Java version: 11
• App Server/Environment: Embedded spring boot
• Frameworks: Spring Boot

[joshfree]

@saragluna could you follow up with @PbALpi7xEX

[PbALpi7xEX]

Documentation typo as well to note...

In https://github.com/Azure/azure-sdk-for-java/tree/main/sdk/appconfiguration/azure-spring-cloud-starter-appconfiguration-config#supported-properties

spring.cloud.azure.appconfiguration.stores[0].feature-flags.enable

Should read

spring.cloud.azure.appconfiguration.stores[0].feature-flags.enabled

Missing a "d" on enable... my feature flags weren't loading at first until I noticed this and decided to try ;-)

[mrm9084]

@PbALpi7xEX I think this might be more than one issue.

I have been able to replicate a similar issue but only with feature flags. Are you having a case where the trigger value changing doesn't cause a refresh too?

Part of the issue might also be that the feature flag label only supports a single label, not multiple. I can work on adding it to this existing work item for feature flags as it is similar. Azure/AppConfiguration#497

Thanks for pointing out the typo. Will update that.

I will continue to try and replicate the configurations not refreshing while I fix the feature flag one.

[PbALpi7xEX]

Are you having a case where the trigger value changing doesn't cause a refresh too?

Yes. Updating the trigger doesn't seem to get the application to refresh it's configuration.

[mrm9084]

After you make the change do you see a logs that looks similar to this?

2021-09-13 11:54:43.640  INFO 25168 --- [         task-3] c.a.d.a.ConfigurationAsyncClient         : Listing ConfigurationSettings - SettingSelector(keyFilter=app.config.refreshTrigger, labelFilter= , acceptDateTime=null, fields=ALL_FIELDS)
2021-09-13 11:54:43.726  INFO 25168 --- [ctor-http-nio-2] c.a.d.a.ConfigurationAsyncClient         : Listed ConfigurationSettings - SettingSelector(keyFilter=app.config.refreshTrigger, labelFilter= , acceptDateTime=null, fields=ALL_FIELDS)
2021-09-13 11:54:43.726  INFO 25168 --- [         task-3] c.a.s.c.config.AppConfigurationRefresh   : Configuration Refresh Event triggered by app.config.refreshTrigger

[PbALpi7xEX]

No

[mrm9084]

Not even the first two? Without them a refresh isn't even checked for? In a previous version of the library did you use refresh?

Refresh check with pull refresh are triggered from "activity", we define activity as requests to Spring Web endpoints. If they are not called then no refresh is done.

You can manually try refreshing by doing calling AppConfigurationRefresh's refreshConfigurations method.

[PbALpi7xEX]

Sorry.. I update a key, then the trigger key, then hit my app to trigger a request... I do see the following in my logs:

2021-09-13 15:34:11,468 INFO com.azure.core.util.logging.ClientLogger [threadPoolExecutor-1] Listing ConfigurationSettings - SettingSelector(keyFilter=app.config.refreshTrigger, labelFilter= , acceptDateTime=null, fields=ALL_FIELDS)
2021-09-13 15:34:11,916 INFO com.azure.core.util.logging.ClientLogger [reactor-http-nio-2] Listed ConfigurationSettings - SettingSelector(keyFilter=app.config.refreshTrigger, labelFilter= , acceptDateTime=null, fields=ALL_FIELDS)
2021-09-13 15:34:11,917 INFO com.azure.core.util.logging.ClientLogger [threadPoolExecutor-1] Listing ConfigurationSettings - SettingSelector(keyFilter=.appconfig*, labelFilter=default, acceptDateTime=null, fields=ALL_FIELDS)
2021-09-13 15:34:12,005 INFO com.azure.core.util.logging.ClientLogger [reactor-http-nio-2] Listed ConfigurationSettings - SettingSelector(keyFilter=.appconfig*, labelFilter=default, acceptDateTime=null, fields=ALL_FIELDS)


But the value I updated isn't coming through and getting refreshed. 

I was using in v1.3.0 and it was working ok...

[mrm9084]

@PbALpi7xEX Did you not update the value of app.config.refreshTrigger? The watch key needs it's value changed. It is how we know to refresh. It is one of the major differences between the 1.3.0 and 2.0.0 versions.

[PbALpi7xEX]

Yes, updated app.config.refreshTrigger

[PbALpi7xEX]

@mrm9084 FYI.. I enabled debug and seeing the following:

2021-09-16 16:24:47,752 DEBUG [threadPoolExecutor-2] com.azure.spring.cloud.config.AppConfigurationRefresh: Skipping configuration refresh check for https://****-secondary.azconfig.io
2021-09-16 16:24:47,753 DEBUG [threadPoolExecutor-2] com.azure.spring.cloud.config.AppConfigurationRefresh: Skipping feature flag refresh check for https://****-secondary.azconfig.io

Something in my config is causing it to skip?

spring.cloud.azure.appconfiguration.stores[0].endpoint=${FAILOVER_APPCONFIG_ENDPOINT}
spring.cloud.azure.appconfiguration.stores[0].enabled=true
spring.cloud.azure.appconfiguration.stores[0].monitoring.enabled=true
spring.cloud.azure.appconfiguration.stores[0].monitoring.refresh-interval=5m
spring.cloud.azure.appconfiguration.stores[0].monitoring.triggers[0].key=app.config.refreshTrigger
spring.cloud.azure.appconfiguration.stores[0].feature-flags.enabled=true
spring.cloud.azure.appconfiguration.stores[0].monitoring.feature-flags.watch-interval=5m
spring.cloud.azure.appconfiguration.stores[0].selects[0].label-filter=,default,${spring.profiles.active}
spring.cloud.azure.appconfiguration.stores[0].feature-flags.label-filter=${spring.profiles.active}
spring.cloud.azure.appconfiguration.stores[0].fail-fast=true

[mrm9084]

@PbALpi7xEX That means refresh is disabled for some reason, or the trigger key didn't change. By any chance does you app.config.refreshTrigger have a label on it? If so it isn't listed in the triggers section.

[mrm9084]

I am working on a sample that might help. It can be found here Azure-Samples/azure-spring-boot-samples#48. Going to add some steps for sample store creation. Hope it helps.

[PbALpi7xEX]

Thanks... still can't get it working... looking at debug a bit closer, and looked into code... seems the etag checks never mismatch and triggering the refresh:

 /**
     * Checks refresh trigger for etag changes. If they have changed a RefreshEventData is published.
     *
     * @param state The refresh state of the endpoint being checked.
     * @param endpoint The App Config Endpoint being checked for refresh.
     * @param refreshInterval Amount of time to wait until next check of this endpoint.
     * @return Refresh event was triggered. No other sources need to be checked.
     */
    private boolean refresh(State state, String endpoint, Duration refreshInterval) {
        Date date = new Date();
        if (date.after(state.getNextRefreshCheck())) {
            for (ConfigurationSetting watchKey : state.getWatchKeys()) {
                ConfigurationSetting watchedKey = clientStore.getWatchKey(watchKey.getKey(), watchKey.getLabel(),
                    endpoint);
                String etag = null;
                // If there is no result, etag will be considered empty.
                // A refresh will trigger once the selector returns a value.
                if (watchedKey != null) {
                    etag = watchedKey.getETag();
                }

                LOGGER.debug(etag + " - " + watchKey.getETag());
                if (etag != null && !etag.equals(watchKey.getETag())) {
                    LOGGER.trace(
                        "Some keys in store [{}] matching the key [{}] and label [{}] is updated, "
                            + "will send refresh event.",
                        endpoint, watchKey.getKey(), watchKey.getLabel());

                    this.eventDataInfo = watchKey.getKey();

                    // Only one refresh Event needs to be call to update all of the
                    // stores, not one for each.
                    LOGGER.info("Configuration Refresh Event triggered by " + eventDataInfo);

                    RefreshEventData eventData = new RefreshEventData(eventDataInfo);
                    publisher.publishEvent(new RefreshEvent(this, eventData, eventData.getMessage()));
                    return true;
                }
            }

            // Just need to reset refreshInterval, if a refresh was triggered it will updated after loading the new
            // configurations.
            StateHolder.setState(state, refreshInterval);
        }

        return false;
    }

I see the logger.debug from above output the following in my console:

2021-09-17 16:32:38,591 DEBUG [threadPoolExecutor-1] com.azure.spring.cloud.config.AppConfigurationRefresh: null - null
2021-09-17 16:32:38,592 DEBUG [threadPoolExecutor-1] com.azure.spring.cloud.config.AppConfigurationRefresh: Skipping configuration refresh check for https://****-secondary.azconfig.io
2021-09-17 16:32:38,691 DEBUG [threadPoolExecutor-1] com.azure.spring.cloud.config.AppConfigurationRefresh: FKtNVZp4e4MtZtPu5Dfj2q4aLYw - FKtNVZp4e4MtZtPu5Dfj2q4aLYw
2021-09-17 16:32:38,692 DEBUG [threadPoolExecutor-1] com.azure.spring.cloud.config.AppConfigurationRefresh: Skipping feature flag refresh check for https://****-secondary.azconfig.io

Looking into the history of my watch key in app config, I don't see any of the etags matching what is output in the debug console... not sure where "FKtNVZp4e4MtZtPu5Dfj2q4aLYw " is coming from, but not found in my watch key etag history at that timestamp.

[mrm9084]

@PbALpi7xEX Can we try you creating a new basic sentinel key. Just to make sure do the following.

az appconfig kv set --name <your-store-name> --key sentinel --value 0 -y

Update you config client app to use the key sentinel, with no label. Once you get it running do:

az appconfig kv set --name <your-store-name> --key sentinel --value 1 -y

[PbALpi7xEX]

@mrm9084 Well interesting , after applying the sentinel key update as specified, and firing a request in the app, I saw the following:

2021-09-20 09:38:14,394 DEBUG [threadPoolExecutor-4] com.azure.spring.cloud.config.AppConfigurationRefresh: ZKQYXJ4mdDIE0pspaCEZgXroWkr - pyfnH2a7xBljKmHsCiFV7axGNzD
2021-09-20 09:38:14,394 INFO  [threadPoolExecutor-4] com.azure.spring.cloud.config.AppConfigurationRefresh: Configuration Refresh Event triggered by sentinel
2021-09-20 09:38:23,768 DEBUG [threadPoolExecutor-4] com.azure.spring.cloud.config.AppConfigurationPropertySourceLocator: PropertySource context [/application/] is added.

So the sentinel key is not using the /application/ prefix in app configuration...

All my other keys are, and loading correctly...

My previous watch key was set with /application/ prefix:

So it seems we shouldn't be prefixing the watch key with /application/ prefix?

[mrm9084]

That is correct. We don't auto add prefixes to watch keys. This was to enable the system to work for people who both want and don't want the prefix on any keys.

Feel free to add the prefix to you watch key, you just need to add it to your watch configuration and everything should work fine. Here is a list of all of the configurations and their default values. https://github.com/Azure/azure-sdk-for-java/tree/main/sdk/appconfiguration/azure-spring-cloud-starter-appconfiguration-config#supported-properties

[PbALpi7xEX]

Thanks... my bad, guess it wasn't clear to me in the documentation.

Using the prefix in my boostrap properties works properly:

2021-09-20 13:16:55,174 DEBUG [threadPoolExecutor-4] com.azure.spring.cloud.config.AppConfigurationRefresh: rl3psxDawV7VEJpkNYQy46N9wEG - RWFHLWJwkltFshI5FDLgWXXBUXY
2021-09-20 13:16:55,174 INFO  [threadPoolExecutor-4] com.azure.spring.cloud.config.AppConfigurationRefresh: Configuration Refresh Event triggered by /application/app.config.refreshTrigger

So i guess this just leaves the issue with feature flag refreshes then.

[mrm9084]

@PbALpi7xEX triggering a refresh this was also updates feature flags. So that can be a work around. I have found the bug with the feature flags. It will be in the next release.

[mrm9084]

@PbALpi7xEX 2.1.1 is released and should fix this last issue. Let me know if you have any further problems.

[PbALpi7xEX]

Thanks @mrm9084

Noticed the update to 2.1.1 yesterday so pulled it in and seems all is working as it should.

Have a good weekend