Bad characters in uri path logs IllegalArgumentException stacktrace

[narras-oss]

Version

4.2.7

Context

During security scan, bad characters are sent in uri path and these result in stacktraces like this one and also in requests failing unexpectedly failures that are hard to discern in exception handler that the problem is a bad request.

The stack traces can put CPU pressure on loggers when invalid request load is high. Suggest to not log stacktrace and make this a "WARN" level message when path can not be parsed.

 io.vertx.ext.web.RoutingContext - Unhandled exception in router java.lang.IllegalArgumentException: Invalid escape sequence: %^&
        at io.vertx.core.http.impl.HttpUtils.decodeUnreserved(HttpUtils.java:275)
        at io.vertx.core.http.impl.HttpUtils.normalizePath(HttpUtils.java:252)
        at io.vertx.ext.web.impl.RoutingContextImpl.normalizedPath(RoutingContextImpl.java:253)
        at io.vertx.ext.web.impl.RouteState.pathMatches(RouteState.java:1017)
        at io.vertx.ext.web.impl.RouteState.matches(RouteState.java:861)
        at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:137)
        at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
        at com.vmware.vidm.federation.ServerVerticle.lambda$start$0(ServerVerticle.java:111)
  at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1128)
        at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:154)
        at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
        at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:55)
        at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:37)
        at io.vertx.core.http.impl.Http1xServerRequestHandler.handle(Http1xServerRequestHandler.java:67)
        at io.vertx.core.http.impl.Http1xServerRequestHandler.handle(Http1xServerRequestHandler.java:30)
        at io.vertx.core.impl.EventLoopContext.emit(EventLoopContext.java:50)
        at io.vertx.core.impl.DuplicatedContext.emit(DuplicatedContext.java:168)
        at io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java:145)
        at io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:156)
        at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:153)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
        at io.netty.handler.codec.http.websocketx.extensions.WebSocketServerExtensionHandler.channelRead(WebSocketServerExtensionHandler.java:99)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.vertx.core.http.impl.Http1xUpgradeToH2CHandler.channelRead(Http1xUpgradeToH2CHandler.java:116)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.vertx.core.http.impl.Http1xOrH2CHandler.end(Http1xOrH2CHandler.java:61)
        at io.vertx.core.http.impl.Http1xOrH2CHandler.channelRead(Http1xOrH2CHandler.java:38)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        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:722)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
        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(Unknown Source)

Do you have a reproducer?

Send "/~!@\||$%^&*()_=-%22;;%27%22:%3C%3E/?]}{" as the path value to a request

Java code to reproduce

URLConnection connection = new URL(serverUri + "/~!@\\||$%^&*()_=-%22;;%27%22:%3C%3E/?]}{").openConnection();
    try(InputStream response = connection.getInputStream()) {
} //fails

[julianladisch]

Workaround: Add a custom error handler: https://github.com/vert-x3/vertx-web/blob/4.2.7/vertx-web/src/main/java/io/vertx/ext/web/impl/RoutingContextImplBase.java#L224-L225

[narras-oss]

I already attached a failure handler. router.route().failureHandler(...);

How to we attach a custom error handler for this case? Please provide a code sample

[vietj]

do you mean the CPU issue arise because of creating an exception or because of logging ?

[pmlopes]

This is a regular log message, all can be controlled using the desired logger config. You can read about it on the manual

https://vertx.io/docs/vertx-core/java/#_logging

[narras-oss]

@vietj The CPU pressure is because of logging stack trace. @pmlopes This log is at ERROR level. We do not want to turn those error logs off. The request is to handle this case in such a way that it doesn't get treated as an unhandled exception

[pmlopes]

@narras-oss what would you suggest? Log as warning?

[narras-oss]

This particular location seems to catching unhandled exceptions, so may not be good to change log level to warning here. I think call to normalizedPath should expect that path could be bad and handle that before it gets bubbled all the way to "handleInHandlerRuntimeFailure".

private void handleInHandlerRuntimeFailure(RouterImpl router, boolean failed, Throwable t) {
    LOG.error("Unhandled exception in router", t);

[pmlopes]

Ok, let's plan like this. This is part of a larger work where we improve the exception hierarchy in web. While you think normalization is not essential to be logged, it can be very useful to troubleshoot why a path is not being accepted to know which escape sequence is wrong.

So I believe we should still log those, but probably as INFO level and any non specific type could be just logging a message without a cause + full stack trace.

[narras-oss]

Yes, sounds good to add INFO log. Important thing is to not log stack trace for invalid requests (possible scans/attacks)

[pmlopes]

Level has been lowered to trace in the 4.x.x series