linagora / james-project

Mirror of Apache James Project
Apache License 2.0
72 stars 62 forks source link

JMAP loooooooong string diagnostic! #5261

Closed chibenwa closed 1 month ago

chibenwa commented 2 months ago
com.fasterxml.jackson.core.exc.StreamConstraintsException: String value length (20054016) exceeds the maximum allowed (20000000, from `StreamReadConstraints.getMaxStringLength()`)
    at com.fasterxml.jackson.core.StreamReadConstraints._constructException(StreamReadConstraints.java:549)
    at com.fasterxml.jackson.core.StreamReadConstraints.validateStringLength(StreamReadConstraints.java:484)
    at com.fasterxml.jackson.core.util.ReadConstrainedTextBuffer.validateStringLength(ReadConstrainedTextBuffer.java:27)
    at com.fasterxml.jackson.core.util.TextBuffer.finishCurrentSegment(TextBuffer.java:946)
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._finishString2(UTF8StreamJsonParser.java:2544)
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._finishAndReturnString(UTF8StreamJsonParser.java:2520)
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser.getText(UTF8StreamJsonParser.java:294)
    at play.api.libs.json.jackson.JsValueDeserializer.deserialize(JacksonJson.scala:202)
    at play.api.libs.json.jackson.JsValueDeserializer.deserialize(JacksonJson.scala:158)
    at play.api.libs.json.jackson.JsValueDeserializer.deserialize(JacksonJson.scala:153)
    at com.fasterxml.jackson.databind.deser.DefaultDeserializationContext.readRootValue(DefaultDeserializationContext.java:342)
    at com.fasterxml.jackson.databind.ObjectMapper._readValue(ObjectMapper.java:4881)
    at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3035)
    at play.api.libs.json.jackson.JacksonJson.parseJsValue(JacksonJson.scala:299)
    at play.api.libs.json.StaticBinding$.parseJsValue(StaticBinding.scala:21)
    at play.api.libs.json.Json$.parse(Json.scala:177)
    at org.apache.james.jmap.json.ResponseSerializer$.deserializeRequestObject(ResponseSerializer.scala:168)
    at org.apache.james.jmap.routes.JMAPApiRoutes.parseRequestObject(JMAPApiRoutes.scala:85)
    at org.apache.james.jmap.routes.JMAPApiRoutes.$anonfun$requestAsJsonStream$1(JMAPApiRoutes.scala:80)
    at org.apache.james.jmap.routes.JMAPApiRoutes.$anonfun$requestAsJsonStream$1$adapted(JMAPApiRoutes.scala:79)
    at reactor.core.scala.publisher.package$.$anonfun$scalaBiConsumer2JavaBiConsumer$1(package.scala:55)
    at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:113)
    at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:129)
    at reactor.core.publisher.FluxMap$MapConditionalSubscriber.onNext(FluxMap.java:224)
    at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onNext(FluxDoFinally.java:113)
    at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:194)
    at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
    at reactor.core.publisher.Operators$BaseFluxToMonoOperator.completePossiblyEmpty(Operators.java:2097)
    at reactor.core.publisher.MonoCollectList$MonoCollectListSubscriber.onComplete(MonoCollectList.java:118)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:260)
    at reactor.core.publisher.FluxMap$MapSubscriber.onComplete(FluxMap.java:144)
    at reactor.netty.channel.FluxReceive.onInboundComplete(FluxReceive.java:415)
    at reactor.netty.channel.ChannelOperations.onInboundComplete(ChannelOperations.java:446)
    at reactor.netty.http.server.HttpServerOperations.onInboundNext(HttpServerOperations.java:818)
    at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:114)
    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 reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java:305)
    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.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
    at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
    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:1407)
    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:918)
    at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:799)
    at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:501)
    at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:399)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
    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)

The front does something stupid for sure but god knows what.

It would be awesome to include the first 1024 chars in the log just so that we know what's happening.

Dod

Locally execute a test demonstrating this gets logged (local james + video)

Arsnael commented 2 months ago

Is it something happening recurrently? A log with the first part of the jmap request would make sense yes for diagnosis. Noted.

chibenwa commented 1 month ago

https://github.com/apache/james-project/pull/2431

I ended up implementing some missing JMAP request validation that made sense for the issue at hand, while I was at it.