You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@james.apache.org by GitBox <gi...@apache.org> on 2022/02/17 08:52:44 UTC
[GitHub] [james-project] chibenwa edited a comment on pull request #886: [JAMES-3715] upgrade to netty 4.1.72.Final
chibenwa edited a comment on pull request #886:
URL: https://github.com/apache/james-project/pull/886#issuecomment-1042697512
## Quick QA
- [X] `openssl s_client -connect 172.17.0.2:993` :green_apple:
- [X] Thunderbird SMTP SSL sending EMail :green_apple:
- [X] Thunderbord IMAP SSL email access - small email - (listing emails and opening it) :green_apple:
- [X] Thunderbord IMAP SSL email access - large mail - (listing emails and opening it) :red_circle:
When I send a multi MB email using Thunderbird, the message is well appended in the INBOX
However when I open to read it, it takes forever for Thunderbird to read it. As if the process hanged.
log:
[reading_big_mail_in_tb.log](https://github.com/apache/james-project/files/8087037/reading_big_mail_in_tb.log)
Fun fact: for one of the test message restarting Thunderbird helped, not for the other one.
- [X] Thunderbird IMAP SSL save the draft (IMAP APPEND) :red_circle:
Thunderbird hangs when saving the draft.
Here are James logs (DEBUG)
```
08:38:32.172 [INFO ] o.a.j.i.n.ImapChannelUpstreamHandler - Connection established from 172.17.0.1
08:38:32.206 [DEBUG] i.n.h.s.SslHandler - [id: 0xc7662865, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39360] HANDSHAKEN: protocol:TLSv1.3 cipher suite:TLS_AES_128_GCM_SHA256
08:38:32.210 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message org.apache.james.imap.message.request.CapabilityRequest@434fb3b2 that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:32.210 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xc7662865, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39360].
08:38:32.212 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message AuthenticateRequest{authType=PLAIN} that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:32.213 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, lineHandler0, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xc7662865, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39360].
08:38:32.222 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message org.apache.james.imap.message.request.CapabilityRequest@656f939a that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:32.222 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xc7662865, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39360].
08:38:32.224 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message EnableRequest{capabilities=[Capability{value=UTF8=ACCEPT}]} that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:32.224 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xc7662865, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39360].
...
Few seconds pass
...
08:38:52.240 [INFO ] o.a.j.i.n.ImapChannelUpstreamHandler - Connection closed for 172.17.0.1
08:38:52.247 [INFO ] o.a.j.i.n.ImapChannelUpstreamHandler - Connection established from 172.17.0.1
08:38:52.300 [DEBUG] i.n.h.s.SslHandler - [id: 0xef5e4890, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39362] HANDSHAKEN: protocol:TLSv1.3 cipher suite:TLS_AES_128_GCM_SHA256
08:38:52.304 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message org.apache.james.imap.message.request.CapabilityRequest@6139c2fb that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:52.304 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xef5e4890, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39362].
08:38:52.305 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message AuthenticateRequest{authType=PLAIN} that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:52.306 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, lineHandler0, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xef5e4890, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39362].
08:38:52.314 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message org.apache.james.imap.message.request.CapabilityRequest@243b50b8 that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:52.314 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xef5e4890, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39362].
08:38:52.316 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message EnableRequest{capabilities=[Capability{value=UTF8=ACCEPT}]} that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:52.316 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xef5e4890, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39362].
08:38:57.972 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message org.apache.james.imap.message.request.NoopRequest@669668ac that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:57.973 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x95a2e755, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39358].
08:38:57.982 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message GetQuotaRootRequest{mailboxName=INBOX} that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:57.982 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x95a2e755, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39358].
08:38:57.993 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message org.apache.james.imap.message.request.IdleRequest@2ce9352a that reached at the tail of the pipeline. Please check your pipeline configuration.
08:38:57.993 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, idleHandler, timeoutHandler, connectionLimitHandler, connectionPerIpLimitHandler, framer, connectionCountHandler, chunkWriteHandler, lineHandler0, requestDecoder, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x95a2e755, L:/172.17.0.2:993 - R:172.17.0.1/172.17.0.1:39358].
```
This indicates a mis-management of IMAP literal management in the frame decoder.
- [ ] Thunderbird IMAP STARTTLS save the draft (IMAP APPEND)
I also had this worrying resource management related log
```
08:45:10.266 [INFO ] o.a.j.p.n.BasicChannelUpstreamHandler - Connection established from 172.17.0.1
08:45:10.294 [DEBUG] i.n.h.s.SslHandler - [id: 0xb73464bf, L:/172.17.0.2:465 - R:172.17.0.1/172.17.0.1:57380] HANDSHAKEN: protocol:TLSv1.3 cipher suite:TLS_AES_128_GCM_SHA256
08:45:10.297 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message PooledSlicedByteBuf(ridx: 0, widx: 19, cap: 19/19, unwrapped: PooledUnsafeDirectByteBuf(ridx: 19, widx: 19, cap: 41)) that reached at the tail of the pipeline. Please check your pipeline configuration.
08:45:10.298 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, connectionLimit, connectionPerIpLimit, framer, chunkHandler, timeoutHandler, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xb73464bf, L:/172.17.0.2:465 - R:172.17.0.1/172.17.0.1:57380].
08:45:10.332 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message PooledSlicedByteBuf(ridx: 0, widx: 37, cap: 37/37, unwrapped: PooledUnsafeDirectByteBuf(ridx: 37, widx: 37, cap: 59)) that reached at the tail of the pipeline. Please check your pipeline configuration.
08:45:10.332 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, connectionLimit, connectionPerIpLimit, framer, chunkHandler, timeoutHandler, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xb73464bf, L:/172.17.0.2:465 - R:172.17.0.1/172.17.0.1:57380].
08:45:10.361 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message PooledSlicedByteBuf(ridx: 0, widx: 37, cap: 37/37, unwrapped: PooledUnsafeDirectByteBuf(ridx: 37, widx: 37, cap: 59)) that reached at the tail of the pipeline. Please check your pipeline configuration.
08:45:10.361 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, connectionLimit, connectionPerIpLimit, framer, chunkHandler, timeoutHandler, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xb73464bf, L:/172.17.0.2:465 - R:172.17.0.1/172.17.0.1:57380].
08:45:10.364 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message PooledSlicedByteBuf(ridx: 0, widx: 21, cap: 21/21, unwrapped: PooledUnsafeDirectByteBuf(ridx: 21, widx: 21, cap: 43)) that reached at the tail of the pipeline. Please check your pipeline configuration.
08:45:10.364 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, connectionLimit, connectionPerIpLimit, framer, chunkHandler, timeoutHandler, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xb73464bf, L:/172.17.0.2:465 - R:172.17.0.1/172.17.0.1:57380].
08:45:10.366 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded inbound message PooledSlicedByteBuf(ridx: 0, widx: 6, cap: 6/6, unwrapped: PooledUnsafeDirectByteBuf(ridx: 6, widx: 6, cap: 28)) that reached at the tail of the pipeline. Please check your pipeline configuration.
08:45:10.366 [DEBUG] i.n.c.DefaultChannelPipeline - Discarded message pipeline : [sslHandler, groupHandler, connectionLimit, connectionPerIpLimit, framer, chunkHandler, timeoutHandler, lineHandler1, coreHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xb73464bf, L:/172.17.0.2:465 - R:172.17.0.1/172.17.0.1:57380].
08:45:10.618 [ERROR] i.n.u.ResourceLeakDetector - LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records:
Created at:
io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:402)
io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:188)
io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:179)
io.netty.buffer.AbstractByteBufAllocator.buffer(AbstractByteBufAllocator.java:116)
io.netty.handler.codec.ByteToMessageDecoder.expandCumulation(ByteToMessageDecoder.java:538)
io.netty.handler.codec.ByteToMessageDecoder$1.cumulate(ByteToMessageDecoder.java:97)
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:274)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1371)
io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1234)
io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1283)
io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507)
io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446)
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
java.base/java.lang.Thread.run(Unknown Source)
```
:orange_circle: Netty debug logs complains of discarded messages and asks us to check our pipeline configuration. Does this indicates we misses some kind of terminal elements in the Netty pipeline>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@james.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: notifications-unsubscribe@james.apache.org
For additional commands, e-mail: notifications-help@james.apache.org