Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Malformed DNS message on MacOS #27605

Closed
kdubb opened this issue Aug 30, 2022 · 15 comments · Fixed by #27653
Closed

Malformed DNS message on MacOS #27605

kdubb opened this issue Aug 30, 2022 · 15 comments · Fixed by #27653
Assignees
Labels
area/logging kind/bug Something isn't working
Milestone

Comments

@kdubb
Copy link
Contributor

kdubb commented Aug 30, 2022

Describe the bug

When starting on macOS this message is printed:

Can not find {} in the classpath, fallback to system defaults. This may result in incorrect DNS resolutions on MacOS.

Notice the {} in the final message.

Expected behavior

Message tells me what can't be found.

Actual behavior

☝️

How to Reproduce?

Start an application in dev mode on macOS.

Output of uname -a or ver

macOS 12

Output of java -version

OpenJDK 17.0.2

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.12.0.Final

Build tool (ie. output of mvnw --version or gradlew --version)

Gradle 7.4.2

Additional information

No response

@kdubb kdubb added the kind/bug Something isn't working label Aug 30, 2022
@geoand
Copy link
Contributor

geoand commented Aug 31, 2022

Is there anything more to that message, like which class is printing it?

@kdubb
Copy link
Contributor Author

kdubb commented Aug 31, 2022

io.net.res.dns.DnsServerAddressStreamProviders

@kdubb
Copy link
Contributor Author

kdubb commented Aug 31, 2022

If it helps, we have a gradle build and I was running it from the Quarkus CLI (e.g. quarkus dev).

@geoand
Copy link
Contributor

geoand commented Aug 31, 2022

So it seems like we intercept the Netty logging via JBossNettyLoggerFactory whose purpose is to redirect the logging to our own JBoss LogManager (cc @galderz who introduced it).

However, it does not seem (at least with a first quick check) that JBoss LogManager handles the {} style for arguments (which seems to be used throughout Netty). @jamezp @dmlloyd is there any was that JBoss Logging could handle this?

@geoand
Copy link
Contributor

geoand commented Aug 31, 2022

If it helps, we have a gradle build and I was running it from the Quarkus CLI (e.g. quarkus dev).

Looking at the code, this should only happen in dev-mode, can you confirm?

@mazenkhalil
Copy link
Contributor

mazenkhalil commented Aug 31, 2022

I am facing what I think a related issue here. Apart from the WARN message, mongoDB connection fails due to DNS issue...

This happens right after upgrading from 2.11.2.Final to 2.12.0.Final. (Apple Silicon MacOS)

2022-08-31 15:12:46,849 WARN  [io.net.res.dns.DnsServerAddressStreamProviders] (build-52) Can not find {} in the classpath, fallback to system defaults. This may result in incorrect DNS resolutions on MacOS.
[INFO] Checking for existing resources in: /Users/mazen/Desktop/elastico/elastico-platform/src/main/kubernetes.
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2022-08-31 15:12:47,940 INFO  [io.quarkus] (Quarkus Main Thread) platform 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.12.0.Final) started in 1.642s. Listening on: http://localhost:8080
2022-08-31 15:12:47,940 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2022-08-31 15:12:47,941 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [cache, cdi, hibernate-validator, kubernetes, micrometer, mongodb-client, oidc, resteasy-reactive, resteasy-reactive-jackson, security, smallrye-context-propagation, smallrye-health, smallrye-openapi, swagger-ui, vertx]
2022-08-31 15:13:06,273 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-1) HTTP Request to / failed, error id: 23287a91-dbad-4d42-85db-5f074c41ec6e-1: io.quarkus.cache.CacheException: com.mongodb.MongoConfigurationException: Failed looking up TXT record for host cluster0.3olzb.mongodb.net
	at io.quarkus.cache.runtime.CacheResultInterceptor$1.apply(CacheResultInterceptor.java:78)
	at io.quarkus.cache.runtime.CacheResultInterceptor$1.apply(CacheResultInterceptor.java:63)
	at io.smallrye.context.impl.wrappers.SlowContextualFunction.apply(SlowContextualFunction.java:21)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni$UniOnItemTransformToUniProcessor.performInnerSubscription(UniOnItemTransformToUni.java:68)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni$UniOnItemTransformToUniProcessor.onItem(UniOnItemTransformToUni.java:57)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription.forwardResult(UniCreateFromCompletionStage.java:63)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:887)
	at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2325)
	at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:144)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription.forward(UniCreateFromCompletionStage.java:51)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage.subscribe(UniCreateFromCompletionStage.java:35)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni$UniOnItemTransformToUniProcessor.performInnerSubscription(UniOnItemTransformToUni.java:81)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni$UniOnItemTransformToUniProcessor.onItem(UniOnItemTransformToUni.java:57)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromKnownItem$KnownItemSubscription.forward(UniCreateFromKnownItem.java:38)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromKnownItem$KnownItemSubscription.access$100(UniCreateFromKnownItem.java:26)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromKnownItem.subscribe(UniCreateFromKnownItem.java:23)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni$UniOnItemTransformToUniProcessor.performInnerSubscription(UniOnItemTransformToUni.java:81)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni$UniOnItemTransformToUniProcessor.onItem(UniOnItemTransformToUni.java:57)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription.forwardResult(UniCreateFromCompletionStage.java:63)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:887)
	at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2325)
	at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:144)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription.forward(UniCreateFromCompletionStage.java:51)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage.subscribe(UniCreateFromCompletionStage.java:35)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniMemoizeOp.subscribe(UniMemoizeOp.java:84)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniMemoizeOp.subscribe(UniMemoizeOp.java:84)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.groups.UniSubscribe.withSubscriber(UniSubscribe.java:52)
	at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2.handle(HttpSecurityRecorder.java:113)
	at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2.handle(HttpSecurityRecorder.java:60)
	at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
	at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:173)
	at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
	at io.quarkus.vertx.http.runtime.filters.accesslog.AccessLogHandler.handle(AccessLogHandler.java:151)
	at io.quarkus.vertx.http.runtime.filters.accesslog.AccessLogHandler.handle(AccessLogHandler.java:93)
	at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
	at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:173)
	at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
	at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup$5.handle(VertxHttpHotReplacementSetup.java:196)
	at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup$5.handle(VertxHttpHotReplacementSetup.java:185)
	at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141)
	at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:54)
	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: com.mongodb.MongoConfigurationException: Failed looking up TXT record for host cluster0.3olzb.mongodb.net
	at com.mongodb.internal.dns.DefaultDnsResolver.resolveAdditionalQueryParametersFromTxtRecords(DefaultDnsResolver.java:133)
	at com.mongodb.ConnectionString.<init>(ConnectionString.java:397)
	at io.quarkus.mongodb.runtime.MongoClients.createMongoConfiguration(MongoClients.java:262)
	at io.quarkus.mongodb.runtime.MongoClients.createReactiveMongoClient(MongoClients.java:126)
	at io.quarkus.mongodb.runtime.MongoClients_Subclass.createReactiveMongoClient$$superforward1(Unknown Source)
	at io.quarkus.mongodb.runtime.MongoClients_Subclass$$function$$5.apply(Unknown Source)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:53)
	at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
	at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:51)
	at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:40)
	at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
	at io.quarkus.mongodb.runtime.MongoClients_Subclass.createReactiveMongoClient(Unknown Source)
	at io.quarkus.mongodb.runtime.MongoClientRecorder.lambda$reactiveMongoClientSupplier$1(MongoClientRecorder.java:68)
	at io.quarkus.mongodb.runtime.MongoClientRecorder$MongoClientSupplier.get(MongoClientRecorder.java:57)
	at io.quarkus.mongodb.reactive.ReactiveMongoClient_afcbcf6dad636d255df730977b21f823ec3c9f2e_Synthetic_Bean.create(Unknown Source)
	at io.quarkus.mongodb.reactive.ReactiveMongoClient_afcbcf6dad636d255df730977b21f823ec3c9f2e_Synthetic_Bean.create(Unknown Source)
	at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:111)
	at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:35)
	at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:32)
	at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26)
	at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69)
	at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:32)
	at io.quarkus.arc.impl.ClientProxies.getApplicationScopedDelegate(ClientProxies.java:19)
	at io.quarkus.mongodb.reactive.ReactiveMongoClient_afcbcf6dad636d255df730977b21f823ec3c9f2e_Synthetic_ClientProxy.arc$delegate(Unknown Source)
	at io.quarkus.mongodb.reactive.ReactiveMongoClient_afcbcf6dad636d255df730977b21f823ec3c9f2e_Synthetic_ClientProxy.getDatabase(Unknown Source)
	at com.elastico.platform.dao.nosql.mongodb.MongoDao.getDatabase(MongoDao.java:229)
	at com.elastico.platform.dao.nosql.mongodb.MongoDao.getCollection(MongoDao.java:225)
	at com.elastico.platform.dao.nosql.mongodb.MongoDao.selectWhere(MongoDao.java:66)
	at com.elastico.platform.metadata.definition.MetadataDefinitionManager.createMetadataDefinition(MetadataDefinitionManager.java:44)
	at com.elastico.platform.metadata.definition.MetadataDefinitionManager.getMetadataDefinitionByDesignName(MetadataDefinitionManager.java:32)
	at com.elastico.platform.metadata.definition.MetadataDefinitionManager_Subclass.getMetadataDefinitionByDesignName$$superforward1(Unknown Source)
	at com.elastico.platform.metadata.definition.MetadataDefinitionManager_Subclass$$function$$4.apply(Unknown Source)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:53)
	at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
	at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:51)
	at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:49)
	at io.quarkus.cache.runtime.CacheResultInterceptor$1.apply(CacheResultInterceptor.java:68)
	... 77 more
Caused by: com.mongodb.MongoConfigurationException: Unable to look up TXT record for host cluster0.3olzb.mongodb.net
	at io.quarkus.mongodb.runtime.dns.MongoDnsClient.resolveTxtRequest(MongoDnsClient.java:152)
	at io.quarkus.mongodb.runtime.dns.MongoDnsClient.getResourceRecordData(MongoDnsClient.java:98)
	at com.mongodb.internal.dns.DefaultDnsResolver.resolveAdditionalQueryParametersFromTxtRecords(DefaultDnsResolver.java:114)
	... 117 more
Caused by: java.lang.IllegalStateException: The current thread cannot be blocked: vert.x-eventloop-thread-1
	at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:30)
	at io.smallrye.mutiny.groups.UniAwait.atMost(UniAwait.java:65)
	at io.quarkus.mongodb.runtime.dns.MongoDnsClient.resolveTxtRequest(MongoDnsClient.java:150)
	... 119 more

@geoand
Copy link
Contributor

geoand commented Aug 31, 2022

I don't think it's the same issue TBH, because it looks like the Mongo driver failing to perform DNS, not Netty.

I would suggest opening a new issue - and sharing a sample application if possible.

@mazenkhalil
Copy link
Contributor

mazenkhalil commented Aug 31, 2022

I found out adding the below dependency removes the WARN message. (I thought this might help identifying the issue)

<dependency>
    <groupId>io.netty</groupId>
    <artifactId>netty-resolver-dns-native-macos</artifactId>
    <version>4.1.79.Final</version>
    <classifier>osx-aarch_64</classifier>
</dependency>

@geoand
Copy link
Contributor

geoand commented Aug 31, 2022

Yeah, that's expected.

@kdubb
Copy link
Contributor Author

kdubb commented Aug 31, 2022

Yeah this issue was about the logging. I'm pretty sure in past versions the message would tell you that the issue was the dependency you added by name.

@jamezp
Copy link
Contributor

jamezp commented Aug 31, 2022

Both JBoss Logging and the JBoss Log Manager do support the MessageFormat. I think the JBossNettyLoggerFactory needs a change. It should be using log.warnf for example it should use log.warnv. The xxxxf versions or for print format and the xxxxv are for message format.

@geoand
Copy link
Contributor

geoand commented Aug 31, 2022

Thanks for the input @jamezp .

But does MessageFormat support {}?

In a quick test I did, it did not work, but I'll have to take another look.

@dmlloyd
Copy link
Member

dmlloyd commented Aug 31, 2022

The JBossNettyLoggerFactory and its corresponding logger should do the same thing that Netty's JdkLogger does and call io.netty.util.internal.logging.MessageFormatter#arrayFormat(format, arguments) to format the arguments, after doing a level check.

@jamezp
Copy link
Contributor

jamezp commented Aug 31, 2022

@geoand Yes. The xxxxv methods use MessageFormat which is the Message {} style.

@geoand
Copy link
Contributor

geoand commented Aug 31, 2022

Thanks folks. I'll provide a fix tomorrow

geoand added a commit to geoand/quarkus that referenced this issue Sep 1, 2022
…mentations

This change essentially makes all the method implementations behave in the same
way Netty's built-in implementations do.

Fixes: quarkusio#27605
geoand added a commit to geoand/quarkus that referenced this issue Sep 1, 2022
…mentations

This change essentially makes all the method implementations behave in the same
way Netty's built-in implementations do.

Fixes: quarkusio#27605

Co-authored-by: David M. Lloyd <david.lloyd@redhat.com>
@geoand geoand self-assigned this Sep 1, 2022
geoand added a commit that referenced this issue Sep 1, 2022
Bring JBossNettyLoggerFactory implementation in line with other implementations
@quarkus-bot quarkus-bot bot added this to the 2.13 - main milestone Sep 1, 2022
@gsmet gsmet modified the milestones: 2.13 - main, 2.12.1.Final Sep 5, 2022
gsmet pushed a commit to gsmet/quarkus that referenced this issue Sep 5, 2022
…mentations

This change essentially makes all the method implementations behave in the same
way Netty's built-in implementations do.

Fixes: quarkusio#27605

Co-authored-by: David M. Lloyd <david.lloyd@redhat.com>
(cherry picked from commit 819f667)
evanchooly pushed a commit to nenros/quarkus that referenced this issue Sep 8, 2022
…mentations

This change essentially makes all the method implementations behave in the same
way Netty's built-in implementations do.

Fixes: quarkusio#27605

Co-authored-by: David M. Lloyd <david.lloyd@redhat.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/logging kind/bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants