search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.78k stars 2.68k forks source link

Unhandled exception in router - Vert.x / RoutingContext #37582

Closed ginccc closed 9 months ago

ginccc commented 11 months ago

Describe the bug

We have been experiencing this exception for the second time, however, we cannot reproduce it.

It is unclear when it happens and how to avoid it. It is fatal tough as the container doesn't recover from it. However, rest endpoints appear to be still reachable, so it could be related to the mongoDB database connection, but there is no direct indication for that. Vert.x is not directly used anywhere in the business logic, but powers quarkus of course.

Any ideas what we can do about it?

Quarkus: 3.6.1 (but was a problem at least for 3.5.3 as well) Code base of the container that has this issue: https://github.com/labsai/EDDI

2023-12-06 22:19:15 ERROR [io.ver.ext.web.RoutingContext]] (vert.x-eventloop-thread-1) Unhandled exception in router
2023-12-07 13:58:50 WARN  [io.ver.cor.imp.BlockedThreadChecker]] (vertx-blocked-thread-checker) Thread Thread[vert.x-eventloop-thread-1,5,main] has been blocked for 2620 ms, time limit is 2000 ms: io.vertx.core.VertxException: Thread blocked
        at io.netty.util.internal.InternalThreadLocalMap.fastGet(InternalThreadLocalMap.java:122)
        at io.netty.util.internal.InternalThreadLocalMap.get(InternalThreadLocalMap.java:115)
        at io.netty.channel.ChannelHandlerAdapter.isSharable(ChannelHandlerAdapter.java:55)
        at io.netty.channel.DefaultChannelPipeline.checkMultiplicity(DefaultChannelPipeline.java:598)
        at io.netty.channel.DefaultChannelPipeline.addLast(DefaultChannelPipeline.java:202)
        at io.netty.channel.DefaultChannelPipeline.addLast(DefaultChannelPipeline.java:195)
        at io.vertx.core.http.impl.HttpServerWorker.configureHttp1OrH2C(HttpServerWorker.java:276)
        at io.vertx.core.http.impl.HttpServerWorker.handleHttp1(HttpServerWorker.java:209)
        at io.vertx.core.http.impl.HttpServerWorker.access$200(HttpServerWorker.java:50)
        at io.vertx.core.http.impl.HttpServerWorker$1.configure(HttpServerWorker.java:180)
        at io.vertx.core.http.impl.Http1xOrH2CHandler.end(Http1xOrH2CHandler.java:59)
        at io.vertx.core.http.impl.Http1xOrH2CHandler.channelRead(Http1xOrH2CHandler.java:38)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
        at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
        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@17.0.9/java.lang.Thread.run(Thread.java:840)

2023-12-07 13:58:53 WARN  [io.ver.cor.imp.BlockedThreadChecker]] (vertx-blocked-thread-checker) Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2742 ms, time limit is 2000 ms: io.vertx.core.VertxException: Thread blocked
        at java.base@17.0.9/sun.nio.ch.EPoll.wait(Native Method)
        at java.base@17.0.9/sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:118)
        at java.base@17.0.9/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:129)
        at java.base@17.0.9/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:141)
        at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
        at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:883)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:526)
        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@17.0.9/java.lang.Thread.run(Thread.java:840)

pom.xml

<?xml version="1.0"?>
<project xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd"
         xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    <modelVersion>4.0.0</modelVersion>
    <groupId>ai.labs</groupId>
    <artifactId>eddi</artifactId>
    <version>5.1.6</version>
    <properties>
        <compiler-plugin.version>3.11.0</compiler-plugin.version>
        <maven.compiler.source>17</maven.compiler.source>
        <maven.compiler.target>17</maven.compiler.target>
        <maven.compiler.release>17</maven.compiler.release>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
        <quarkus.microprofile.version>3.0.0.Final</quarkus.microprofile.version>
        <quarkus.platform.artifact-id>quarkus-bom</quarkus.platform.artifact-id>
        <quarkus.platform.group-id>io.quarkus.platform</quarkus.platform.group-id>
        <quarkus.platform.version>3.6.1</quarkus.platform.version>
        <quarkus-plugin.version>3.6.1</quarkus-plugin.version>
        <quarkus-logger-manager.version>3.0.2</quarkus-logger-manager.version>
        <jandex-maven-plugin.version>3.1.6</jandex-maven-plugin.version>
        <maven.compiler.parameters>true</maven.compiler.parameters>
        <surefire-plugin.version>3.0.0</surefire-plugin.version>
        <failsafe-plugin.version>3.0.0</failsafe-plugin.version>
        <failsafe.useModulePath>false</failsafe.useModulePath>
        <war-plugin.version>3.3.2</war-plugin.version>
        <dependency.version.lombok>1.18.30</dependency.version.lombok>
        <quarkus.jgit.version>2.2.0</quarkus.jgit.version>
        <skipITs>true</skipITs>
    </properties>
    <dependencyManagement>
        <dependencies>
            <dependency>
                <groupId>${quarkus.platform.group-id}</groupId>
                <artifactId>${quarkus.platform.artifact-id}</artifactId>
                <version>${quarkus.platform.version}</version>
                <type>pom</type>
                <scope>import</scope>
            </dependency>
        </dependencies>
    </dependencyManagement>
    <dependencies>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-container-image-docker</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-resteasy</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-resteasy-jackson</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-resteasy-multipart</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-rest-client</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-jackson</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-smallrye-openapi</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-smallrye-context-propagation</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-swagger-ui</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-arc</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-scheduler</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-smallrye-health</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-micrometer-registry-prometheus</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-oidc</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-keycloak-authorization</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkiverse.loggingmanager</groupId>
            <artifactId>quarkus-logging-manager</artifactId>
            <version>${quarkus-logger-manager.version}</version>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>io.quarkiverse.jgit</groupId>
            <artifactId>quarkus-jgit</artifactId>
            <version>${quarkus.jgit.version}</version>
        </dependency>
        <dependency>
            <groupId>org.scala-lang</groupId>
            <artifactId>scala-library</artifactId>
            <version>2.13.10</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>io.swagger.core.v3</groupId>
            <artifactId>swagger-annotations</artifactId>
            <version>2.2.9</version>
        </dependency>
        <dependency>
            <groupId>de.undercouch</groupId>
            <artifactId>bson4jackson</artifactId>
            <version>2.13.1</version>
            <exclusions>
                <exclusion>
                    <groupId>com.fasterxml.jackson.core</groupId>
                    <artifactId>jackson-core</artifactId>
                </exclusion>
                <exclusion>
                    <groupId>com.fasterxml.jackson.core</groupId>
                    <artifactId>jackson-annotations</artifactId>
                </exclusion>
                <exclusion>
                    <groupId>com.fasterxml.jackson.core</groupId>
                    <artifactId>jackson-databind</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>com.kjetland</groupId>
            <artifactId>mbknor-jackson-jsonschema_2.13</artifactId>
            <version>1.0.39</version>
            <exclusions>
                <exclusion>
                    <groupId>com.fasterxml.jackson.core</groupId>
                    <artifactId>jackson-core</artifactId>
                </exclusion>
                <exclusion>
                    <groupId>com.fasterxml.jackson.core</groupId>
                    <artifactId>jackson-annotations</artifactId>
                </exclusion>
                <exclusion>
                    <groupId>com.fasterxml.jackson.core</groupId>
                    <artifactId>jackson-databind</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <version>${dependency.version.lombok}</version>
        </dependency>
        <dependency>
            <groupId>javax.annotation</groupId>
            <artifactId>javax.annotation-api</artifactId>
            <version>1.3.2</version>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-mongodb-client</artifactId>
        </dependency>
        <dependency>
            <groupId>org.infinispan</groupId>
            <artifactId>infinispan-core</artifactId>
            <version>14.0.21.Final</version>
        </dependency>
        <dependency>
            <groupId>org.infinispan</groupId>
            <artifactId>infinispan-component-annotations</artifactId>
            <version>14.0.21.Final</version>
            <scope>compile</scope>
        </dependency>
        <dependency>
            <groupId>org.apache.commons</groupId>
            <artifactId>commons-lang3</artifactId>
            <version>3.12.0</version>
            <scope>compile</scope>
        </dependency>
        <dependency>
            <groupId>com.jayway.jsonpath</groupId>
            <artifactId>json-path</artifactId>
            <version>2.8.0</version>
        </dependency>
        <dependency>
            <groupId>com.github.rholder</groupId>
            <artifactId>snowball-stemmer</artifactId>
            <version>1.3.0.581.1</version>
        </dependency>
        <dependency>
            <groupId>org.thymeleaf</groupId>
            <artifactId>thymeleaf</artifactId>
            <version>3.0.15.RELEASE</version>
        </dependency>
        <dependency>
            <groupId>ognl</groupId>
            <artifactId>ognl</artifactId>
            <version>3.1.26</version>
        </dependency>
        <dependency>
            <groupId>org.eclipse.jetty</groupId>
            <artifactId>jetty-client</artifactId>
            <version>12.0.3</version>
        </dependency>
        <dependency>
            <groupId>javax.transaction</groupId>
            <artifactId>javax.transaction-api</artifactId>
            <version>1.3</version>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-junit5</artifactId>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>io.rest-assured</groupId>
            <artifactId>rest-assured</artifactId>
            <version>5.2.1</version>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>org.mockito</groupId>
            <artifactId>mockito-core</artifactId>
            <version>4.8.1</version>
            <scope>test</scope>
        </dependency>
    </dependencies>
    <build>
        <plugins>
            <plugin>
                <groupId>io.smallrye</groupId>
                <artifactId>jandex-maven-plugin</artifactId>
                <version>${jandex-maven-plugin.version}</version>
                <executions>
                    <execution>
                        <id>make-index</id>
                        <goals>
                            <goal>jandex</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
            <plugin>
                <groupId>${quarkus.platform.group-id}</groupId>
                <artifactId>quarkus-maven-plugin</artifactId>
                <version>${quarkus.platform.version}</version>
                <extensions>true</extensions>
                <executions>
                    <execution>
                        <goals>
                            <goal>build</goal>
                            <goal>generate-code</goal>
                            <goal>generate-code-tests</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-compiler-plugin</artifactId>
                <version>${compiler-plugin.version}</version>
                <configuration>
                    <compilerArgs>
                        <arg>-parameters</arg>
                    </compilerArgs>
                    <annotationProcessorPaths>
                        <path>
                            <groupId>org.projectlombok</groupId>
                            <artifactId>lombok</artifactId>
                            <version>${dependency.version.lombok}</version>
                        </path>
                    </annotationProcessorPaths>
                </configuration>
            </plugin>
            <plugin>
                <groupId>io.quarkus</groupId>
                <artifactId>quarkus-maven-plugin</artifactId>
                <version>${quarkus-plugin.version}</version>
                <executions>
                    <execution>
                        <goals>
                            <goal>build</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-surefire-plugin</artifactId>
                <version>${surefire-plugin.version}</version>
                <configuration>
                    <systemProperties>
                        <java.util.logging.manager>org.jboss.logmanager.LogManager</java.util.logging.manager>
                        <!--suppress UnresolvedMavenProperty -->
                        <maven.home>${maven.home}</maven.home>
                    </systemProperties>
                </configuration>
            </plugin>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-failsafe-plugin</artifactId>
                <version>${failsafe-plugin.version}</version>
                <executions>
                    <execution>
                        <goals>
                            <goal>integration-test</goal>
                            <goal>verify</goal>
                        </goals>
                        <configuration>
                            <systemPropertyVariables>
                                <native.image.path>${project.build.directory}/${project.build.finalName}-runner</native.image.path>
                                <java.util.logging.manager>org.jboss.logmanager.LogManager</java.util.logging.manager>
                                <!--suppress UnresolvedMavenProperty -->
                                <maven.home>${maven.home}</maven.home>
                            </systemPropertyVariables>
                        </configuration>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>
    <profiles>
        <profile>
            <id>native</id>
            <activation>
                <property>
                    <name>native</name>
                </property>
            </activation>
            <properties>
                <skipITs>false</skipITs>
                <quarkus.package.type>native</quarkus.package.type>
            </properties>
        </profile>
    </profiles>
</project>

Expected behavior

No response

Actual behavior

No response

How to Reproduce?

No response

Output of uname -a or ver

No response

Output of java -version

No response

Quarkus version or git rev

No response

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

No response

Additional information

No response

cescoffier commented 11 months ago

From the stack trace it is hard to see what's going on. I'm a bit concerned that the epoll wait is done on the event loop - this is definitely not right. But it's hard to say from where it comes.

I would recommend switching to resteasy reactive.

ginccc commented 11 months ago

thanks for the feedback. Switching to resteasy reactive is a good idea, but will take some time to do. In the meantime, what else can we do? This is a base quarkus functionality and the container's sudden break in readiness and inability to recover from it is deeply concerning.

cescoffier commented 11 months ago

We would need a standalone minimal reproducer to see what's going on. For sure epoll from the event loop is incorrect.

ginccc commented 11 months ago

Unfortunately it only happened twice in the last few months.. Unsure what event causes it.

cescoffier commented 11 months ago

Unfortunately, without a reproducer, it's impossible to understand what's going on.

ginccc commented 11 months ago

we have updated to resteasy-reactive & rest-client-reactive like suggested. We will observe it to see if this issue appears again with the reactive components. If so, we'll report it here again. I am just worried that the best we will be getting is the very same stack trace from above, so not sure how we can improve the error report the next time around.

cescoffier commented 11 months ago

You have a dependency on infinispan, which also use netty. Why not using the extension? The issue may comes from an interaction with something that is not correctly integrated.

ginccc commented 10 months ago

From what I know the quarkus extension for infinispan covers only the client but doesn't allow infinispan to run embedded..

I have potentially more information around this issue, as the last time i saw it happening it appeared after an InterruptedException that was triggered due to a configured timeout.

Caused by: java.lang.InterruptedException
        at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:386)
        at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2073)
        ... 20 more

2023-12-14 15:54:25 ERROR [io.ver.ext.web.RoutingContext]] (vert.x-eventloop-thread-1) Unhandled exception in router
2023-12-14 19:48:23 ERROR [io.ver.ext.web.RoutingContext]] (vert.x-eventloop-thread-1) Unhandled exception in router
2023-12-14 19:48:23 ERROR [io.ver.ext.web.RoutingContext]] (vert.x-eventloop-thread-0) Unhandled exception in router
cescoffier commented 10 months ago

Unfortunately, I need a minimal standalone reproducer to investigate the issue.

geoand commented 9 months ago

Closing for lack of a reproducer

iampkuhz commented 9 months ago

@geoand I've also faced with the same problem.

here is my TRACE log of the same thread before this error message occurs:

2024-02-04 13:46:03.235+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Calling the handler 2024-02-04 13:46:03.237+08:00 | vert.x-eventloop-thread-1 | TRACE | RouterImpl | Router: 19149411 accepting request POST http://172.16.0.5:8549/ 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Route matches: RouteState{metadata=null, path='null', name=null, order=1, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[org.hyperledger.besu.ethereum.api.jsonrpc.JsonRpcHttpService$$Lambda$886/0x00007f0a84515228@5f7f834e], failureHandlers=null, added=true, pattern=null, groups=null, useNormalizedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=true} 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Calling the handler 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context. 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Route matches: RouteState{metadata=null, path='null', name=null, order=2, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[org.hyperledger.besu.ethereum.api.jsonrpc.JsonRpcHttpService$$Lambda$887/0x00007f0a84515450@196f6366], failureHandlers=null, added=true, pattern=null, groups=null, useNormalizedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=true} 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Calling the handler 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Route matches: RouteState{metadata=null, path='null', name=null, order=3, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.vertx.ext.web.handler.impl.CorsHandlerImpl@1edc9f0a], failureHandlers=null, added=true, pattern=null, groups=null, useNormalizedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=true} 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Calling the handler 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Route matches: RouteState{metadata=null, path='null', name=null, order=4, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.vertx.ext.web.handler.impl.BodyHandlerImpl@6389e44b], failureHandlers=null, added=true, pattern=null, groups=null, useNormalizedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=true} 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Calling the handler 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Route matches: RouteState{metadata=null, path='/', name=null, order=8, enabled=true, methods=[POST], consumes=null, emptyBodyPermittedWithConsumes=false, produces=[io.vertx.ext.web.impl.ParsableMIMEValue@fd630a66], contextHandlers=[org.hyperledger.besu.ethereum.api.handlers.JsonRpcParserHandler$$Lambda$897/0x00007f0a8451a080@3495725e, org.hyperledger.besu.ethereum.api.handlers.TimeoutHandler$$Lambda$900/0x00007f0a8451a930@582c0f2a, io.vertx.ext.web.impl.BlockingHandlerDecorator@555d6c07], failureHandlers=null, added=true, pattern=null, groups=null, useNormalizedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=true, exclusive=false, exactPath=true} 2024-02-04 13:46:03.238+08:00 | vert.x-eventloop-thread-1 | TRACE | RoutingContext | Calling the handler 2024-02-04 13:46:03.949+08:00 | vert.x-eventloop-thread-1 | ERROR | RoutingContext | Unhandled exception in router

My scenario is that we use blockscout to call besu for some block data to built explorer and something went wrong when acquiring data. Since TRACE is currently the most verbose log of besu and we still could not find any useful info, I recommend to improve the log.

I've checked the RoutingContextImplBase.java(who print this error log) in vertx as well as JsonRpcHttpService.java in besu.

in RoutingContextImplBase.java(who print this error log), it failed to find appropriate handlers:

Handler<RoutingContext> errorHandler = router.getErrorHandlerByStatusCode(code);
    if (errorHandler != null) {
      try {
        errorHandler.handle(this);
      } catch (Throwable t) {
        LOG.error("Error in error handler", t);
      }
    } else {
      // if there are no user defined handlers, we will log the exception
      LOG.error("Unhandled exception in router", failure);
    }

Maybe we could add more handlers for other http error code in besu:

private Router buildRouter() {
    // Handle json rpc requests
    final Router router = Router.router(vertx);
    router.route().handler(this::createSpan);

    // Verify Host header to avoid rebind attack.
    router.route().handler(checkAllowlistHostHeader());
    router.errorHandler(403, new Logging403ErrorHandler());
   .....
geoand commented 9 months ago

@iampkuhz if you could attach a sample application that behaves as you describe, we can look into it more

VanKuang commented 1 day ago

I got very similar issue, which was triggered by nessus scan which sending a bad request - null authority/path, and it was catched by RoutingContextImpl in vertx-web. Workaround for me is adding error handler for 400/404:

void init(@Observes Router router) {
    router.errorHandler(400, ctx -> {});
}

It won't work if your http root-path is not "/", because VertxHttpRecoder only notify http router and main router will be same as http router if root-path is "/".

Not sure VertxHttpRecoder can also notify main router?

cescoffier commented 23 hours ago

Which Quarkus version are you using? We had a bug with http requests without host header.

VanKuang commented 17 hours ago

Which Quarkus version are you using? We had a bug with http requests without host header.

hi @cescoffier 3.14.2

cescoffier commented 12 hours ago

Try with 3.15. Do you know the HTTP version for the request without host?

VanKuang commented 11 hours ago

Try with 3.15. Do you know the HTTP version for the request without host?

HTTP_1_0

cescoffier commented 8 hours ago

Host is not mandatory in HTTP 1. So it should work.

A reproducer would be super useful

VanKuang commented 4 hours ago

Host is not mandatory in HTTP 1. So it should work.

A reproducer would be super useful

Upgrade to 3.15 seem to fix the issue with HTTP_1_0 request as it(RoutingContextImpl) add checking for version, but not really fix the issue as request can be http 1.1

Here is my http request to reproduce the issue:

GET http://localhost:1024/test
Accept: application/json
Content-Type: */*
host:[localhost:1024
cescoffier commented 2 hours ago

Http 1.1 considers the host header as mandatory. So, if the request does not have it, it's an invalid http request.