I'm trying to debug some low-level issues with various Vertx components in my Quarkus application and it would be helpful to have the Vert logs to do that (e.g. io.vertx.core). I assume it's something simple like this:
$ ./mvnw quarkus:dev -Dquarkus.log.level=DEBUG
But I don't see any Vertx logs (e.g. io.vertx.core) unless I get an exception.
For example using the Reactive starter https://github.com/quarkusio/quarkus-quickstarts/tree/main/getting-started
I see logs like this but no Vertx logs (e.g. io.vertx.core)
2023-03-07 11:08:44,649 DEBUG [io.ver.cor.log.LoggerFactory] (Quarkus Main Thread) Using io.vertx.core.logging.SLF4JLogDelegateFactory
2023-03-07 11:08:44,669 DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (Quarkus Main Thread) Vert.x Cache configured to: /var/folders/_q/xg6cqp056f5cfb_5ky14645r0000gp/T/vertx-cache/1938671968490402924
2023-03-07 11:08:44,673 DEBUG [io.net.uti.ResourceLeakDetector] (Quarkus Main Thread) -Dio.netty.leakDetection.level: simple
2023-03-07 11:08:44,673 DEBUG [io.net.uti.ResourceLeakDetector] (Quarkus Main Thread) -Dio.netty.leakDetection.targetRecords: 4
2023-03-07 11:08:44,677 DEBUG [io.net.cha.MultithreadEventLoopGroup] (Quarkus Main Thread) -Dio.netty.eventLoopThreads: 20
2023-03-07 11:08:44,683 DEBUG [io.net.cha.nio.NioEventLoop] (Quarkus Main Thread) -Dio.netty.noKeySetOptimization: false
2023-03-07 11:08:44,683 DEBUG [io.net.cha.nio.NioEventLoop] (Quarkus Main Thread) -Dio.netty.selectorAutoRebuildThreshold: 512
2023-03-07 11:08:44,683 DEBUG [io.net.uti.int.PlatformDependent] (Quarkus Main Thread) org.jctools-core.MpscChunkedArrayQueue: available
2023-03-07 11:08:44,692 DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (Quarkus Main Thread) Vertx has Native Transport Enabled: false
2023-03-07 11:08:44,748 DEBUG [io.net.uti.NetUtil] (vert.x-eventloop-thread-1) -Djava.net.preferIPv4Stack: false
2023-03-07 11:08:44,749 DEBUG [io.net.uti.NetUtil] (vert.x-eventloop-thread-1) -Djava.net.preferIPv6Addresses: false
2023-03-07 11:08:44,751 DEBUG [io.net.uti.NetUtilInitializations] (vert.x-eventloop-thread-1) Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1%lo0)
2023-03-07 11:08:44,751 DEBUG [io.net.uti.NetUtil] (vert.x-eventloop-thread-1) Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128
2023-03-07 11:08:44,762 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.numHeapArenas: 20
2023-03-07 11:08:44,762 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.numDirectArenas: 20
2023-03-07 11:08:44,762 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.pageSize: 8192
2023-03-07 11:08:44,762 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.maxOrder: 3
2023-03-07 11:08:44,763 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.chunkSize: 65536
2023-03-07 11:08:44,763 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.smallCacheSize: 256
2023-03-07 11:08:44,763 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.normalCacheSize: 64
2023-03-07 11:08:44,763 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2023-03-07 11:08:44,763 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.cacheTrimInterval: 8192
2023-03-07 11:08:44,763 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.cacheTrimIntervalMillis: 0
2023-03-07 11:08:44,764 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.useCacheForAllThreads: false
2023-03-07 11:08:44,764 DEBUG [io.net.buf.PooledByteBufAllocator] (vert.x-eventloop-thread-1) -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
2023-03-07 11:08:44,790 DEBUG [io.net.buf.ByteBufUtil] (vert.x-eventloop-thread-1) -Dio.netty.allocator.type: pooled
2023-03-07 11:08:44,791 DEBUG [io.net.buf.ByteBufUtil] (vert.x-eventloop-thread-1) -Dio.netty.threadLocalDirectBufferSize: 0
2023-03-07 11:08:44,791 DEBUG [io.net.buf.ByteBufUtil] (vert.x-eventloop-thread-1) -Dio.netty.maxThreadLocalCharBufferSize: 16384
2023-03-07 11:08:44,839 INFO [io.quarkus] (Quarkus Main Thread) getting-started-reactive 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.16.4.Final) started in 5.647s. Listening on: http://localhost:8080
But then on exception I see Vertx logs (e.g. io.vertx.core)
2023-03-07 10:31:42,453 DEBUG [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (vert.x-eventloop-thread-1) Restarting handler chain for exception exception: javax.ws.rs.NotFoundException: HTTP 404 Not Found
at org.jboss.resteasy.reactive.server.handlers.RestInitialHandler.handle(RestInitialHandler.java:71)
at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:94)
at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
at org.jboss.resteasy.reactive.server.handlers.RestInitialHandler.beginProcessing(RestInitialHandler.java:48)
at org.jboss.resteasy.reactive.server.vertx.ResteasyReactiveVertxHandler.handle(ResteasyReactiveVertxHandler.java:23)
at org.jboss.resteasy.reactive.server.vertx.ResteasyReactiveVertxHandler.handle(ResteasyReactiveVertxHandler.java:10)
at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:101)
at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:87)
at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:140)
at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
at io.vertx.ext.web.handler.impl.StaticHandlerImpl.lambda$sendStatic$1(StaticHandlerImpl.java:290)
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:569)
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:829)
UPDATE
Here's what I get from below answer:
No logs for Vertx
./mvnw quarkus:dev -Dquarkus.log.level=INFO -Dquarkus.log.category."io.vertx".level=TRACE
2023-03-09 09:49:39,345 WARN [io.qua.config] (Quarkus Main Thread) Unrecognized configuration key "quarkus.log.category.io.vertx.level" was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
Also setting root level to trace still doesn't show anything unless maybe the package names are different?
./mvnw quarkus:dev -Dquarkus.log.level=TRACE -Dquarkus.log.min-level=TRACE
2023-03-09 09:56:08,207 INFO [io.quarkus] (Quarkus Main Thread) getting-started-reactive 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.16.4.Final) started in 5.094s. Listening on: http://localhost:8080
2023-03-09 09:56:08,208 INFO [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2023-03-09 09:56:08,208 INFO [io.quarkus] (Quarkus Main Thread) Installed features: [cdi, resteasy-reactive, smallrye-context-propagation, vertx]
2023-03-09 09:56:26,642 DEBUG [io.net.uti.Recycler] (vert.x-eventloop-thread-0) -Dio.netty.recycler.maxCapacityPerThread: 4096
2023-03-09 09:56:26,643 DEBUG [io.net.uti.Recycler] (vert.x-eventloop-thread-0) -Dio.netty.recycler.ratio: 8
2023-03-09 09:56:26,643 DEBUG [io.net.uti.Recycler] (vert.x-eventloop-thread-0) -Dio.netty.recycler.chunkSize: 32
2023-03-09 09:56:26,643 DEBUG [io.net.uti.Recycler] (vert.x-eventloop-thread-0) -Dio.netty.recycler.blocking: false
2023-03-09 09:56:26,651 DEBUG [io.net.buf.AbstractByteBuf] (vert.x-eventloop-thread-0) -Dio.netty.buffer.checkAccessible: true
2023-03-09 09:56:26,651 DEBUG [io.net.buf.AbstractByteBuf] (vert.x-eventloop-thread-0) -Dio.netty.buffer.checkBounds: true
2023-03-09 09:56:26,652 DEBUG [io.net.uti.ResourceLeakDetectorFactory] (vert.x-eventloop-thread-0) Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@7c21ea4e
2023-03-09 09:56:26,682 DEBUG [io.net.han.cod.com.ZlibCodecFactory] (vert.x-eventloop-thread-0) -Dio.netty.noJdkZlibDecoder: false
2023-03-09 09:56:26,683 DEBUG [io.net.han.cod.com.ZlibCodecFactory] (vert.x-eventloop-thread-0) -Dio.netty.noJdkZlibEncoder: false
2023-03-09 09:56:26,690 TRACE [io.ver.ext.web.imp.RouterImpl] (vert.x-eventloop-thread-0) Router: 197957170 accepting request GET http://127.0.0.1:8080/hello
2023-03-09 09:56:26,693 TRACE [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-0) Route matches: RouteState{metadata=null, path='null', name=null, order=-2147483648, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.quarkus.vertx.http.runtime.VertxHttpRecorder$11@34b6843f], failureHandlers=null, added=true, pattern=null, groups=null, useNormalizedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=true}
2023-03-09 09:56:26,693 TRACE [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-0) Calling the handler
2023-03-09 09:56:26,701 TRACE [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-0) Route matches: RouteState{metadata=null, path='null', name=null, order=-199, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.quarkus.resteasy.reactive.server.runtime.ResteasyReactiveRecorder$13@3d38ec6c], failureHandlers=null, added=true, pattern=null, groups=null, useNormalizedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=true}
2023-03-09 09:56:26,702 TRACE [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-0) Calling the handler
2023-03-09 09:56:26,702 TRACE [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-0) Route matches: RouteState{metadata=null, path='null', name=null, order=-2, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.quarkus.vertx.http.runtime.VertxHttpRecorder$6@3f68fd55], failureHandlers=null, added=true, pattern=null, groups=null, useNormalizedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=true}
2023-03-09 09:56:26,702 TRACE [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-0) Calling the handler
2023-03-09 09:56:26,702 TRACE [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-0) Route matches: RouteState{metadata=null, path='null', name=null, order=10000, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.quarkus.vertx.http.runtime.StaticResourcesRecorder$1@60c2ad4e, io.quarkus.vertx.http.runtime.StaticResourcesRecorder$1@26672884, io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2@5c46eba8], failureHandlers=null, added=true, pattern=null, groups=null, useNormalizedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=true}
2023-03-09 09:56:26,703 TRACE [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-0) Calling the handler
2023-03-09 09:56:26,704 TRACE [io.ver.ext.web.han.imp.StaticHandlerImpl] (vert.x-eventloop-thread-0) File to serve is /Users/DENNCH3/trash/quarkus-quickstarts/getting-started-reactive/target/classes/META-INF/resources/hello
2023-03-09 09:56:26,706 TRACE [io.ver.ext.web.han.imp.StaticHandlerImpl] (vert.x-eventloop-thread-0) File to serve is /Users/DENNCH3/trash/quarkus-quickstarts/getting-started-reactive/src/main/resources/META-INF/resources/hello
2023-03-09 09:56:26,706 TRACE [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-0) Route matches: RouteState{metadata=null, path='/', name=null, order=20500, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[org.jboss.resteasy.reactive.server.vertx.ResteasyReactiveVertxHandler@3950330d], failureHandlers=null, added=true, pattern=null, groups=null, useNormalizedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=true, exclusive=false, exactPath=false}
2023-03-09 09:56:26,707 TRACE [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-0) Calling the handler
2023-03-09 09:56:26,712 TRACE [io.qua.arc.requestContext] (executor-thread-0) Activate new
io.quarkus.arc.ManagedContext.activate(ManagedContext.java:15)
io.quarkus.resteasy.reactive.common.runtime.ArcThreadSetupAction.activateInitial(ArcThreadSetupAction.java:18)
org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.requireCDIRequestScope(AbstractResteasyReactiveContext.java:250)
org.jboss.resteasy.reactive.server.handlers.InstanceHandler.handle(InstanceHandler.java:25)
io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:112)
org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
...
2023-03-09 09:56:26,718 TRACE [io.qua.arc.requestContext] (executor-thread-0) Deactivate
io.quarkus.resteasy.reactive.common.runtime.ArcThreadSetupAction$1.deactivate(ArcThreadSetupAction.java:37)
org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:194)
io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
...
2023-03-09 09:56:26,719 TRACE [io.qua.arc.requestContext] (executor-thread-0) Destroy 45a4fc69
io.quarkus.resteasy.reactive.common.runtime.ArcThreadSetupAction$1.close(ArcThreadSetupAction.java:27)
org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.close(AbstractResteasyReactiveContext.java:113)
org.jboss.resteasy.reactive.server.core.ResteasyReactiveRequestContext.close(ResteasyReactiveRequestContext.java:361)
org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:196)
io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
...
--
Tests paused
Press [r] to resume testing, [o] Toggle test output, [:] for the terminal, [h] for more options>
