Runtime defaults config supplied via RunTimeConfigurationDefaultBuildItem are not overridden on restart during dev mode

[machi1990]

Describe the bug

An extension author can provide default values via the RunTimeConfigurationDefaultBuildItem, this is the case for dev services. In dev mode, the same key can have different values on each restart e.g a new container was spun by testcontainers, taking a new random/different port. The behaviour I am seeing with dev services is that a new restart of the container having a different port does not update the config value and the first supplied value is always cached.

Expected behavior

Defaults values supplied via RunTimeConfigurationDefaultBuildItem should always be taken into account on each app restart in dev mode and not cache the first value.

Actual behavior

The first default value of a config item is cached and subsequent overrides of the values are not taken into account.

This is the case for datasource devservices and mongo devservices. This leads to connection failures.

To Reproduce

The issue can be reproduced with the current quickstarts e.g the mongodb one

Steps to reproduce the behavior:

1. Using the https://github.com/quarkusio/quarkus-quickstarts/tree/development/mongodb-quickstart quickstart
2. Open the vim src/main/resources/application.properties configuration file and add the following entry only

quarkus.mongodb.devservices.image-name=mongo

while making sure that the connection-string property is commented out or removed.
3. start the quickstart in dev mode with mvn quarkus:dev
4. visits the http://localhost:8080/q/dev/io.quarkus.quarkus-vertx-http/config page and observe the auto-configured connection string.
Also observe the output of the docker ps command to see the current mongo container mapped port. This should match the port in the config page.
5. Open the vim src/main/resources/application.properties configuration file and change the image tag to mongo:4.4.5 this will lead to a new container being spin up.

quarkus.mongodb.devservices.image-name=mongo:4.4.5

while making sure that the connection-string property is commented out or removed.
6. Observe the logs of the command in (3) and you'll see logs like below

(cluster-ClusterId{value='6095541bbe5033399414ba51', description='null'}-localhost:49194) Exception in monitor thread while connecting to server localhost:49194: com.mongodb.MongoSocketOpenException: Exception opening socket
	at com.mongodb.internal.connection.AsynchronousSocketChannelStream$OpenCompletionHandler.failed(AsynchronousSocketChannelStream.java:124)
	at java.base/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:129)
	at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.finishConnect(UnixAsynchronousSocketChannelImpl.java:283)
	at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.finish(UnixAsynchronousSocketChannelImpl.java:198)
	at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.onEvent(UnixAsynchronousSocketChannelImpl.java:213)
	at java.base/sun.nio.ch.EPollPort$EventHandlerTask.run(EPollPort.java:306)
	at java.base/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.net.ConnectException: Connection refused
	at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.checkConnect(Native Method)
	at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.finishConnect(UnixAsynchronousSocketChannelImpl.java:252)
	... 7 more

Observing the output from docker ps again will show that a new container was started by devservices but the app is using the old container which can be observed in the config page.

[machi1990]

/cc @stuartwdouglas @geoand @radcortez

[geoand]

@stuartwdouglas this initially seems to be caused by:

        if (liveReloadBuildItem.isLiveReload()) {
            return;
        }

in ConfigBuildSteps#generateConfigSources which was added in:

86c18ff

Even if I remove the guard, the new defaults still aren't applied properly.

[machi1990]

Even if I remove the guard, the new defaults still aren't applied properly.

Also further down in

quarkus/core/deployment/src/main/java/io/quarkus/deployment/configuration/RunTimeConfigurationGenerator.java

Lines 516 to 531 in c988b9a

	if (!devMode) {
	//we don't need these in devmode
	//including it would just cache the first values
	//but these can already just be read directly, as we are in the same JVM
	for (Map.Entry<String, String> entry : specifiedRunTimeDefaultValues.entrySet()) {
	clinit.invokeVirtualMethod(HM_PUT, specifiedRunTimeValues, clinit.load(entry.getKey()),
	clinit.load(entry.getValue()));
	}
	}
	for (Map.Entry<String, String> entry : runTimeDefaults.entrySet()) {
	if (!specifiedRunTimeDefaultValues.containsKey(entry.getKey())) {
	// only add entry if the user didn't override it
	clinit.invokeVirtualMethod(HM_PUT, specifiedRunTimeValues, clinit.load(entry.getKey()),
	clinit.load(entry.getValue()));
	}
	}

. it appears that on app restart the configurations are cached in specifiedRunTimeDefaultValues and are considered as user supplied value instead of a extension initialized default value.

[radcortez]

I was not able to reproduce this. I did try with with a QuarkusDevModeTest and tried with separate extension:

2021-05-20 12:57:40,243 WARN  [io.qua.agr.dep.AgroalProcessor] (build-43) The Agroal dependency is present but no JDBC datasources have been defined.
2021-05-20 12:57:40,248 WARN  [io.qua.dat.dep.dev.DevServicesDatasourceProcessor] (build-33) Unable to determine a database type for default datasource
2021-05-20 12:57:40,254 INFO  [org.jberet] (build-40) JBERET000030: Resolved job file:/Users/radcortez/Code/open-source/quarkiverse-jberet/integration-tests/chunk/target/classes/META-INF/batch-jobs/auctions.xml
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2021-05-20 12:57:41,339 WARN  [io.qua.config] (Quarkus Main Thread) Unrecognized configuration key "quarkus.test.runtime.my.prop" was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
2021-05-20 12:57:41,375 INFO  [org.jbe.schedule-executor] (Quarkus Main Thread) JBERET072500: Created JobScheduler: io.quarkiverse.jberet.runtime.QuarkusJobScheduler@3dcf0da0, based on resource: null
quarkus.test.runtime.my.prop=1234
2021-05-20 12:57:41,494 INFO  [io.quarkus] (Quarkus Main Thread) quarkus-jberet-integration-tests-chunk 0.0.6-SNAPSHOT on JVM (powered by Quarkus 1.13.2.Final) started in 1.626s. Listening on: http://localhost:8080
2021-05-20 12:57:41,495 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2021-05-20 12:57:41,495 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, jberet, jberet-rest, mutiny, narayana-jta, rest-client, rest-client-jsonb, resteasy, resteasy-jsonb, smallrye-context-propagation]
2021-05-20 12:58:11,680 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (vert.x-worker-thread-0) File change detected: /Users/radcortez/Code/open-source/quarkiverse-jberet/integration-tests/chunk/src/main/resources/application.properties
2021-05-20 12:58:11,710 INFO  [io.quarkus] (Quarkus Main Thread) quarkus-jberet-integration-tests-chunk stopped in 0.028s
2021-05-20 12:58:11,771 WARN  [io.qua.agr.dep.AgroalProcessor] (build-17) The Agroal dependency is present but no JDBC datasources have been defined.
2021-05-20 12:58:11,779 INFO  [org.jberet] (build-14) JBERET000030: Resolved job file:/Users/radcortez/Code/open-source/quarkiverse-jberet/integration-tests/chunk/target/classes/META-INF/batch-jobs/auctions.xml
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2021-05-20 12:58:12,074 WARN  [io.qua.config] (Quarkus Main Thread) Unrecognized configuration key "quarkus.test.runtime.my.prop" was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
quarkus.test.runtime.my.prop=5678
2021-05-20 12:58:12,096 INFO  [io.quarkus] (Quarkus Main Thread) quarkus-jberet-integration-tests-chunk 0.0.6-SNAPSHOT on JVM (powered by Quarkus 1.13.2.Final) started in 0.383s. Listening on: http://localhost:8080
2021-05-20 12:58:12,096 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2021-05-20 12:58:12,097 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, jberet, jberet-rest, mutiny, narayana-jta, rest-client, rest-client-jsonb, resteasy, resteasy-jsonb, smallrye-context-propagation]
2021-05-20 12:58:12,097 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (vert.x-worker-thread-0) Hot replace total time: 0.419s

I added a property quarkus.test.runtime.my.prop in a RunTimeConfigurationDefaultBuildItem. I run in dev mode and the property was first set to 1234 and changed via application.properties to 5678 and it seemed to work.

Any thoughts?

[machi1990]

I was not able to reproduce this. I did try with with a QuarkusDevModeTest and tried with separate extension:

2021-05-20 12:57:40,243 WARN  [io.qua.agr.dep.AgroalProcessor] (build-43) The Agroal dependency is present but no JDBC datasources have been defined.
2021-05-20 12:57:40,248 WARN  [io.qua.dat.dep.dev.DevServicesDatasourceProcessor] (build-33) Unable to determine a database type for default datasource
2021-05-20 12:57:40,254 INFO  [org.jberet] (build-40) JBERET000030: Resolved job file:/Users/radcortez/Code/open-source/quarkiverse-jberet/integration-tests/chunk/target/classes/META-INF/batch-jobs/auctions.xml
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2021-05-20 12:57:41,339 WARN  [io.qua.config] (Quarkus Main Thread) Unrecognized configuration key "quarkus.test.runtime.my.prop" was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
2021-05-20 12:57:41,375 INFO  [org.jbe.schedule-executor] (Quarkus Main Thread) JBERET072500: Created JobScheduler: io.quarkiverse.jberet.runtime.QuarkusJobScheduler@3dcf0da0, based on resource: null
quarkus.test.runtime.my.prop=1234
2021-05-20 12:57:41,494 INFO  [io.quarkus] (Quarkus Main Thread) quarkus-jberet-integration-tests-chunk 0.0.6-SNAPSHOT on JVM (powered by Quarkus 1.13.2.Final) started in 1.626s. Listening on: http://localhost:8080
2021-05-20 12:57:41,495 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2021-05-20 12:57:41,495 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, jberet, jberet-rest, mutiny, narayana-jta, rest-client, rest-client-jsonb, resteasy, resteasy-jsonb, smallrye-context-propagation]
2021-05-20 12:58:11,680 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (vert.x-worker-thread-0) File change detected: /Users/radcortez/Code/open-source/quarkiverse-jberet/integration-tests/chunk/src/main/resources/application.properties
2021-05-20 12:58:11,710 INFO  [io.quarkus] (Quarkus Main Thread) quarkus-jberet-integration-tests-chunk stopped in 0.028s
2021-05-20 12:58:11,771 WARN  [io.qua.agr.dep.AgroalProcessor] (build-17) The Agroal dependency is present but no JDBC datasources have been defined.
2021-05-20 12:58:11,779 INFO  [org.jberet] (build-14) JBERET000030: Resolved job file:/Users/radcortez/Code/open-source/quarkiverse-jberet/integration-tests/chunk/target/classes/META-INF/batch-jobs/auctions.xml
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2021-05-20 12:58:12,074 WARN  [io.qua.config] (Quarkus Main Thread) Unrecognized configuration key "quarkus.test.runtime.my.prop" was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
quarkus.test.runtime.my.prop=5678
2021-05-20 12:58:12,096 INFO  [io.quarkus] (Quarkus Main Thread) quarkus-jberet-integration-tests-chunk 0.0.6-SNAPSHOT on JVM (powered by Quarkus 1.13.2.Final) started in 0.383s. Listening on: http://localhost:8080
2021-05-20 12:58:12,096 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2021-05-20 12:58:12,097 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, jberet, jberet-rest, mutiny, narayana-jta, rest-client, rest-client-jsonb, resteasy, resteasy-jsonb, smallrye-context-propagation]
2021-05-20 12:58:12,097 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (vert.x-worker-thread-0) Hot replace total time: 0.419s

I added a property quarkus.test.runtime.my.prop in a RunTimeConfigurationDefaultBuildItem. I run in dev mode and the property was first set to 1234 and changed via application.properties to 5678 and it seemed to work.

Any thoughts?

Thanks for having a look at it @radcortez .

Yes, if you change the value in application.properties it will work. But the issue here is that, the same value being changed by giving a different value to RunTimeConfigurationDefaultBuildItem other than the original value on first start. That won't be take into account because on restart the first value is considered as a user supplied value while it was given by RunTimeConfigurationDefaultBuildItem.

[radcortez]

Ok, to make if I understood correctly:

You mean, that if a RunTimeConfigurationDefaultBuildItem is set up before running dev mode, for instance a property is set to 1234, but I override it with 5678, on the first dev run you get 1234?

[machi1990]

Ok, to make if I understood correctly:

You mean, that if a RunTimeConfigurationDefaultBuildItem is set up before running dev mode, for instance a property is set to 1234, but I override it with 5678, on the first dev run you get 1234?

Yes, let me clarify further: A configuration key is set to 1234 via RunTimeConfigurationDefaultBuildItem and then overridden to 5678 via RunTimeConfigurationDefaultBuildItem, it will remain with 1234 (at this point this is considered to be user supplied value)

[radcortez]

Ah you mean you have two RunTimeConfigurationDefaultBuildItem for the same key, where one overrides the other?

[machi1990]

Ah you mean you have two RunTimeConfigurationDefaultBuildItem for the same key, where one overrides the other?

Yes, but the overriding happening on restart. This is the configuration we have for various dev services e.g a new container port was initiated, so we change the connection string for MongoDB/Redis connection .

[radcortez]

I see. I was now able to reproduce the issue with a regular test case.

The generate config class is not reloaded, but a reinit method called again on dev mode. In this particular case, we don't have the proper values to generate the reinit properly, because we only have them on a dev mode reload. @stuartwdouglas, can you help us understand this here, please? :)