linagora / james-project

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

[Postgres] JMAP Email/set update patch issue? #5145

Closed Arsnael closed 5 months ago

Arsnael commented 6 months ago

Seen this in the logs when running a jmap perf tests with pg-app:

{"timestamp":"2024-03-27T07:19:24.934Z","level":"INFO","thread":"reactor-tcp-epoll-1","logger":"org.apache.james.jmap.method.EmailSetUpdatePerformer","message":"Illegal argument in Email/set update","context":"default","exception":"java.lang.IllegalArgumentException: List((,List(JsonValidationError(List(KeywordName($seen) is an invalid entry in an Email/set update patch),List()))))\n\tat org.apache.james.jmap.method.EmailSetUpdatePerformer.$anonfun$update$7(EmailSetUpdatePerformer.scala:101)\n\tat scala.util.Either$LeftProjection.map(Either.scala:614)\n\tat org.apache.james.jmap.method.EmailSetUpdatePerformer.$anonfun$update$6(EmailSetUpdatePerformer.scala:101)\n\tat scala.util.Either.flatMap(Either.scala:352)\n\tat org.apache.james.jmap.method.EmailSetUpdatePerformer.$anonfun$update$4(EmailSetUpdatePerformer.scala:100)\n\tat scala.collection.StrictOptimizedIterableOps.map(StrictOptimizedIterableOps.scala:100)\n\tat scala.collection.StrictOptimizedIterableOps.map$(StrictOptimizedIterableOps.scala:87)\n\tat scala.collection.immutable.Map$Map1.map(Map.scala:239)\n\tat org.apache.james.jmap.method.EmailSetUpdatePerformer.update(EmailSetUpdatePerformer.scala:96)\n\tat org.apache.james.jmap.method.EmailSetUpdatePerformer.$anonfun$update$2(EmailSetUpdatePerformer.scala:90)\n\tat scala.Option.map(Option.scala:242)\n\tat org.apache.james.jmap.method.EmailSetUpdatePerformer.update(EmailSetUpdatePerformer.scala:90)\n\tat org.apache.james.jmap.method.EmailSetMethod.$anonfun$doProcess$2(EmailSetMethod.scala:54)\n\tat reactor.core.scala.publisher.SMono.$anonfun$flatMap$1(SMono.scala:585)\n\tat reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:132)\n\tat reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129)\n\tat reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129)\n\tat reactor.core.publisher.Operators$BaseFluxToMonoOperator.completePossiblyEmpty(Operators.java:2097)\n\tat reactor.core.publisher.MonoCollectList$MonoCollectListSubscriber.onComplete(MonoCollectList.java:118)\n\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:368)\n\tat reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onComplete(FluxConcatMap.java:276)\n\tat reactor.core.publisher.Operators.complete(Operators.java:137)\n\tat reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:144)\n\tat reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:83)\n\tat reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:76)\n\tat reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:165)\n\tat reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:122)\n\tat reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74)\n\tat reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:122)\n\tat reactor.core.publisher.SerializedSubscriber.onNext(SerializedSubscriber.java:99)\n\tat reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onNext(FluxRetryWhen.java:177)\n\tat reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete(MonoFlatMap.java:245)\n\tat reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:305)\n\tat reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:82)\n\tat org.jooq.impl.Internal$1.onNext(Internal.java:749)\n\tat org.jooq.impl.R2DBC$Forwarding.onNext(R2DBC.java:242)\n\tat reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89)\n\tat reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:129)\n\tat reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onNext(MonoFlatMapMany.java:250)\n\tat reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:194)\n\tat reactor.core.publisher.FluxFilterFuseable$FilterFuseableConditionalSubscriber.onNext(FluxFilterFuseable.java:337)\n\tat reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)\n\tat reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)\n\tat reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)\n\tat io.r2dbc.postgresql.util.FluxDiscardOnCancel$FluxDiscardOnCancelSubscriber.onNext(FluxDiscardOnCancel.java:91)\n\tat reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onNext(FluxDoFinally.java:113)\n\tat reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:129)\n\tat reactor.core.publisher.FluxCreate$BufferAsyncSink.drain(FluxCreate.java:880)\n\tat reactor.core.publisher.FluxCreate$BufferAsyncSink.next(FluxCreate.java:805)\n\tat reactor.core.publisher.FluxCreate$SerializedFluxSink.next(FluxCreate.java:163)\n\tat io.r2dbc.postgresql.client.ReactorNettyClient$Conversation.emit(ReactorNettyClient.java:684)\n\tat io.r2dbc.postgresql.client.ReactorNettyClient$BackendMessageSubscriber.emit(ReactorNettyClient.java:936)\n\tat io.r2dbc.postgresql.client.ReactorNettyClient$BackendMessageSubscriber.onNext(ReactorNettyClient.java:810)\n\tat io.r2dbc.postgresql.client.ReactorNettyClient$BackendMessageSubscriber.onNext(ReactorNettyClient.java:716)\n\tat reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:129)\n\tat reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)\n\tat reactor.core.publisher.FluxMap$MapConditionalSubscriber.onNext(FluxMap.java:224)\n\tat reactor.core.publisher.FluxMap$MapConditionalSubscriber.onNext(FluxMap.java:224)\n\tat reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:294)\n\tat reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:403)\n\tat reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:426)\n\tat reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:114)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)\n\tat io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)\n\tat io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:333)\n\tat io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:454)\n\tat io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)\n\tat io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)\n\tat io.r2dbc.postgresql.client.SSLSessionHandlerAdapter.channelRead(SSLSessionHandlerAdapter.java:83)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)\n\tat io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1475)\n\tat io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1338)\n\tat io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1387)\n\tat io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529)\n\tat io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468)\n\tat io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)\n\tat io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)\n\tat io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)\n\tat io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)\n\tat io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:509)\n\tat io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:407)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Unknown Source)\n"}

Is it a problem in the gatling simulation after a change or is it a more general problem to the jmap method?

Investigate and fix.

Arsnael commented 6 months ago

This message I still observed, will investigate

Arsnael commented 6 months ago

Not specific to postgresql implem, I noticed the same message when trying with distributed on sandbox.

Likely an issue in the request itself in james-gatling, will investigate

Arsnael commented 6 months ago

=> https://github.com/linagora/james-gatling/pull/176

Culprit being younger me, from 4 years ago (oups^^')

Can't believe we never caught that before though, meaning the flag updates for jmap rfc were always wrong until now for jmap perf tests^^'